search

tarantool / test-run

Tarantool functional testing framework
14 stars 15 forks source link

Unnecessary timeout in diff tests #413

Open ImeevMA opened 11 months ago

ImeevMA commented 11 months ago

If Tarantool is aborted, diff tests (at least from sql/) only produce diff after a timeout.

For example, let's say that we applied this diff:

diff --git a/src/box/sql/parse.y b/src/box/sql/parse.y
index fb9332c80..f65f91d57 100644
--- a/src/box/sql/parse.y
+++ b/src/box/sql/parse.y
@@ -399,6 +399,7 @@ ifexists(A) ::= .            {A = 0;}
 //
 cmd ::= createkw(X) VIEW ifnotexists(E) nm(Y) eidlist_opt(C)
           AS select(S). {
+  assert(0);
   if (!pParse->parse_only) {
     create_view_def_init(&pParse->create_view_def, &Y, &X, C, S, E);
     pParse->initiateTTrans = true;

And ran the following command in tarantool/test/:

./test-run.py sql/gh-4111-format-in-sysview. -j1

Result on the commit just before test: bump test-run to new version:

Detected build mode: Debug

======================================================================================
WORKR TEST                                            PARAMS          RESULT
---------------------------------------------------------------------------------
2023-11-09 10:20:28.973 [207074] main/103/app I> update replication_synchro_quorum = 1
2023-11-09 10:20:28.973 [207074] main/103/app I> replicaset uuid 74bac459-c3b8-454f-b6ae-ff9bf46128b7
2023-11-09 10:20:28.976 [207074] snapshot/101/main I> saving snapshot `/tmp/t/001_sql/app/00000000000000000000.snap.inprogress'
2023-11-09 10:20:28.981 [207074] snapshot/101/main I> done
2023-11-09 10:20:28.982 [207074] main/103/app I> ready to accept requests
2023-11-09 10:20:28.982 [207074] main/105/gc I> wal/engine cleanup is resumed
2023-11-09 10:20:28.982 [207074] main/103/app/box.load_cfg I> set 'replication_sync_timeout' configuration option to 100
2023-11-09 10:20:28.982 [207074] main/103/app/box.load_cfg I> set 'log' configuration option to "/tmp/t/001_sql/app.log"
2023-11-09 10:20:28.982 [207074] main/103/app/box.load_cfg I> set 'vinyl_max_tuple_size' configuration option to 5242880
2023-11-09 10:20:28.982 [207074] main/103/app/box.load_cfg I> set 'memtx_max_tuple_size' configuration option to 5242880
2023-11-09 10:20:28.982 [207074] main/103/app/box.load_cfg I> set 'listen' configuration option to "/tmp/t/001_sql/app.i"
2023-11-09 10:20:28.982 [207074] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Nov  9 11:28:13 2023
2023-11-09 10:20:28.983 [207074] main/114/console/unix/:/tmp/t/001_sql/app.c/socket I> started
2023-11-09 10:20:28.983 [207074] main I> entering the event loop
tarantool: ./src/box/sql/parse.y:402: yy_reduce: Assertion `0' failed.
[001] sql/gh-4111-format-in-sysview.test.lua          memtx           
[001] 
[001] [Instance "app" killed by signal: 6 (SIGABRT)]
[001] Found assertion fail in the results file [/tmp/t/001_sql/app.log]:
[001] [ fail ]
[Main process] Got failed test; gently terminate all workers...
[001] Worker "001_sql" got failed test; stopping the server...
---------------------------------------------------------------------------------

The result on commit test: bump test-run to new version:

Detected build mode: Debug

======================================================================================
WORKR TEST                                            PARAMS          RESULT
---------------------------------------------------------------------------------
No output during 10 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 20 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 30 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 40 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 51 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 61 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 71 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 81 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 91 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
No output during 101 seconds. Will abort after 120 seconds without output. List of workers not reporting the status:
- 001_sql [sql/gh-4111-format-in-sysview.test.lua, memtx] at /tmp/t/001_sql/gh-4111-format-in-sysview.result:0
[001] sql/gh-4111-format-in-sysview.test.lua          memtx           Test timeout of 110 secs reached [ fail ]
[001] 
[001] Test failed! Result content mismatch:
[001] --- sql/gh-4111-format-in-sysview.result Thu Nov  9 09:58:19 2023
[001] +++ /tmp/t/rejects/sql/gh-4111-format-in-sysview.reject Thu Nov  9 10:18:39 2023
[001] @@ -11,18 +11,6 @@
[001]  - true
[001]  ...
[001]  box.execute([[CREATE VIEW t AS SELECT "name" FROM "_vspace" y]])
[001] ----
[001] -- row_count: 1
[001] -...
[001]  box.execute([[SELECT * from t WHERE "name" = 'T']])
[001] ----
[001] -- metadata:
[001] -  - name: name
[001] -    type: string
[001] -  rows:
[001] -  - ['T']
[001] -...
[001] +[Lost current connection]
[001]  box.execute([[DROP VIEW t]])
[001] ----
[001] -- row_count: 1
[001] -...
[001] 
[001] [test-run server "app"] Last 15 lines of the log file /tmp/t/001_sql/app.log:
[001] 2023-11-09 10:16:49.213 [194592] main/103/app I> update replication_synchro_quorum = 1
[001] 2023-11-09 10:16:49.214 [194592] main/103/app I> replicaset uuid 6575c51c-7049-4c3b-9aa7-acf72a872bff
[001] 2023-11-09 10:16:49.217 [194592] snapshot/101/main I> saving snapshot `/tmp/t/001_sql/app/00000000000000000000.snap.inprogress'
[001] 2023-11-09 10:16:49.221 [194592] snapshot/101/main I> done
[001] 2023-11-09 10:16:49.222 [194592] main/103/app I> ready to accept requests
[001] 2023-11-09 10:16:49.222 [194592] main/105/gc I> wal/engine cleanup is resumed
[001] 2023-11-09 10:16:49.222 [194592] main/103/app/box.load_cfg I> set 'replication_sync_timeout' configuration option to 100
[001] 2023-11-09 10:16:49.222 [194592] main/103/app/box.load_cfg I> set 'log' configuration option to "/tmp/t/001_sql/app.log"
[001] 2023-11-09 10:16:49.222 [194592] main/103/app/box.load_cfg I> set 'vinyl_max_tuple_size' configuration option to 5242880
[001] 2023-11-09 10:16:49.222 [194592] main/103/app/box.load_cfg I> set 'memtx_max_tuple_size' configuration option to 5242880
[001] 2023-11-09 10:16:49.222 [194592] main/103/app/box.load_cfg I> set 'listen' configuration option to "/tmp/t/001_sql/app.i"
[001] 2023-11-09 10:16:49.222 [194592] main/106/checkpoint_daemon I> scheduled next checkpoint for Thu Nov  9 11:20:21 2023
[001] 2023-11-09 10:16:49.223 [194592] main/114/console/unix/:/tmp/t/001_sql/app.c/socket I> started
[001] 2023-11-09 10:16:49.223 [194592] main I> entering the event loop
[001] tarantool: ./src/box/sql/parse.y:402: yy_reduce: Assertion `0' failed.
[Main process] Got failed test; gently terminate all workers...
[001] Worker "001_sql" got failed test; stopping the server...
---------------------------------------------------------------------------------

Note that the latter result is better because it shows the difference, but only after a timeout. It would be great if the timeout could be removed in such cases.