From: "Alexander V. Tikhonov" <avtikhon@tarantool.org>
To: Kirill Yukhin <kyukhin@tarantool.org>,
Alexander Turenko <alexander.turenko@tarantool.org>
Cc: tarantool-patches@dev.tarantool.org
Subject: [Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946
Date: Thu, 25 Jun 2020 14:25:10 +0300 [thread overview]
Message-ID: <1bc869413c7d116ba5fcdd2a05c756729fedd7d4.1593084206.git.avtikhon@tarantool.org> (raw)
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
next reply other threads:[~2020-06-25 11:25 UTC|newest]
Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top
2020-06-25 11:25 Alexander V. Tikhonov [this message]
2020-06-25 11:25 ` [Tarantool-patches] [PATCH v2 2/2] test: fix flaky box/net.box_readahead_gh-3958 test Alexander V. Tikhonov
2020-06-29 12:18 ` Alexander Turenko
2020-07-03 13:45 ` Alexander V. Tikhonov
2020-07-03 14:09 ` Kirill Yukhin
2020-06-29 11:49 ` [Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946 Alexander Turenko
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1bc869413c7d116ba5fcdd2a05c756729fedd7d4.1593084206.git.avtikhon@tarantool.org \
--to=avtikhon@tarantool.org \
--cc=alexander.turenko@tarantool.org \
--cc=kyukhin@tarantool.org \
--cc=tarantool-patches@dev.tarantool.org \
--subject='Re: [Tarantool-patches] [PATCH v2 1/2] test: fix flaky box/net.box_call_blocks_gh-946' \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox