From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp48.i.mail.ru (smtp48.i.mail.ru [94.100.177.108]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id A1D974429E1 for ; Wed, 17 Jun 2020 15:00:52 +0300 (MSK) From: "Alexander V. Tikhonov" Date: Wed, 17 Jun 2020 15:00:48 +0300 Message-Id: <8ce5e510f40a14583da6fc83c6f8f127d134a3c5.1592395183.git.avtikhon@tarantool.org> Subject: [Tarantool-patches] [PATCH v1] test: fix flaky box/net.box_readahead_gh-3958 test List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Kirill Yukhin , Sergey Bronnikov Cc: tarantool-patches@dev.tarantool.org, 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