test: engine/ddl.test.lua flaky fails on index counter checks

[avtikhon]

Tarantool version:
Tarantool 2.5.0-158-g357281133
Target: Linux-x86_64-RelWithDebInfo
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS:-O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type
CXX_FLAGS:-O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type

OS version:
Fedora 31

Bug description:
https://gitlab.com/tarantool/tarantool/-/jobs/606635367

 [159] --- engine/ddl.result	Mon Jun 22 21:45:31 2020
 [159] +++ engine/ddl.reject	Mon Jun 22 22:00:01 2020
 [159] @@ -2558,7 +2558,7 @@
 [159]  ...
 [159]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [159]  ---
 [159] -- true
 [159] +- false
 [159]  ...
 [159]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [159]  ---
 [159] @@ -2570,24 +2570,24 @@
 [159]  ...
 [159]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [159]  ---
 [159] +- false
 [159] +...
 [159] +inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [159] +---
 [159]  - true
 [159]  ...
 [159] +box.snapshot()
 [159] +---
 [159] +- ok
 [159] +...
 [159] +inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [159] +---
 [159] +- false
 [159] +...
 [159]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [159]  ---
 [159]  - true
 [159]  ...
 [159] -box.snapshot()
 [159] ----
 [159] -- ok
 [159] -...
 [159] -inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [159] ----
 [159] -- true
 [159] -...
 [159] -inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [159] ----
 [159] -- true
 [159] -...
 [159]  box.space.test:drop()
 [159]  ---
 [159]  ...
 [159] 
 [159] Last 15 lines of Tarantool Log file [Instance "box"][/build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box.log]:
 [159] 2020-06-22 21:59:01.270 [32461] vinyl.dump.0/104/task I> writing `/build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000275.index'
 [159] 2020-06-22 21:59:01.270 [32461] main/108/vinyl.scheduler I> 599/0: dump completed
 [159] 2020-06-22 21:59:01.270 [32461] main/108/vinyl.scheduler I> dumped 305714 bytes in 0.0 s, rate 99.8 MB/s
 [159] 2020-06-22 21:59:01.270 [32461] main/121/console/unix/: I> vinyl checkpoint completed
 [159] 2020-06-22 21:59:01.270 [32461] main/108/vinyl.scheduler I> 599/0: started compacting range (-inf..inf), runs 4/4
 [159] 2020-06-22 21:59:01.270 [32461] vinyl.compaction.0/102/task I> writing `/build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000277.run'
 [159] 2020-06-22 21:59:01.271 [32461] main I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/00000000000000003036.snap
 [159] 2020-06-22 21:59:01.271 [32461] main I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/00000000000000002736.vylog
 [159] 2020-06-22 21:59:01.271 [32461] main/105/gc I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000247.index
 [159] 2020-06-22 21:59:01.271 [32461] main/105/gc I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000247.run
 [159] 2020-06-22 21:59:01.271 [32461] main/105/gc I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000249.index
 [159] 2020-06-22 21:59:01.272 [32461] main/105/gc I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000249.run
 [159] 2020-06-22 21:59:01.273 [32461] wal I> removed /build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/00000000000000003036.xlog
 [159] 2020-06-22 21:59:01.280 [32461] vinyl.compaction.0/102/task I> writing `/build/usr/src/debug/tarantool-2.5.0.158/test/var/159_engine/box/599/0/00000000000000000277.index'
 [159] 2020-06-22 21:59:01.287 [32461] main/108/vinyl.scheduler I> 599/0: completed compacting range (-inf..inf)

Steps to reproduce:

l=0 ; while ./test-run.py -j20 `for r in {1..100} ; do echo engine/ddl.test.lua ; done` 2>/dev/null ; do l=$(($l+1)) ; echo ======== $l ============= ; done

Found that the root cause of the issue is the different number of primary and secondary keys. Check the following patch:

diff --git a/test/engine/ddl.test.lua b/test/engine/ddl.test.lua
index 1d77705dd..1991212d0 100644
--- a/test/engine/ddl.test.lua
+++ b/test/engine/ddl.test.lua
@@ -966,6 +966,9 @@ math.randomseed(os.time())
 s = box.schema.space.create('test', {engine = engine})
 _ = s:create_index('pk')
 
+log = require('log')
+log.info("ERROR ======= BEFORE 1 ======= PK " .. box.space.test.index.pk:count())
+
 inspector:cmd("setopt delimiter ';'")
 
 box.begin()
@@ -1005,17 +1008,36 @@ end;
 
 inspector:cmd("setopt delimiter ''");
 
+log.info("ERROR ======= AFTER 1 ======= PK " .. box.space.test.index.pk:count())
+
 fiber = require('fiber')
 ch = fiber.channel(1)
 
 _ = fiber.create(function() gen_load() ch:put(true) end)
 _ = box.space.test:create_index('sk', {unique = false, parts = {2, 'unsigned'}})
+
+log.info("ERROR ======= BEFORE 1 ======= PK " .. box.space.test.index.pk:count())
+log.info("ERROR ======= BEFORE 1 ======= SK " .. box.space.test.index.sk:count())
+
 ch:get()
 
+log.info("ERROR ======= AFTER 1 ======= PK " .. box.space.test.index.pk:count())
+log.info("ERROR ======= AFTER 1 ======= SK " .. box.space.test.index.sk:count())
+
+
 _ = fiber.create(function() gen_load() ch:put(true) end)
 _ = box.space.test:create_index('tk', {unique = true, parts = {3, 'unsigned'}})
+
+log.info("ERROR ======= BEFORE 2 ======= PK " .. box.space.test.index.pk:count())
+log.info("ERROR ======= BEFORE 2 ======= SK " .. box.space.test.index.sk:count())
+log.info("ERROR ======= BEFORE 2 ======= TK " .. box.space.test.index.tk:count())
+
 ch:get()
 
+log.info("ERROR ======= AFTER 2 ======= PK " .. box.space.test.index.pk:count())
+log.info("ERROR ======= AFTER 2 ======= SK " .. box.space.test.index.sk:count())
+log.info("ERROR ======= AFTER 2 ======= TK " .. box.space.test.index.tk:count())
+
 inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 

run it on dev1 host with command:

( c=0 ; while ./test-run.py --builddir /tnt -j 160 `for r in {1..200} ; do echo engine/ddl.test.lua ; done` --force --long --no-output-timeout=20 ; do date ; c=$(($c+1)) ; echo ALX $c ; done ; echo ALX $c ) | tee a.log &

and check results, with command:

grep -RI ERROR var/*_engine/ 2>/dev/null

find, like:
a) for passed tests:

 ======= BEFORE 1 ======= PK 0
 ======= AFTER 1 ======= PK 1000
 ======= BEFORE 1 ======= PK 974
 ======= BEFORE 1 ======= SK 974
 ======= AFTER 1 ======= PK 957
 ======= AFTER 1 ======= SK 957
 ======= BEFORE 2 ======= PK 931
 ======= BEFORE 2 ======= SK 931
 ======= BEFORE 2 ======= TK 931
 ======= AFTER 2 ======= PK 920
 ======= AFTER 2 ======= SK 920
 ======= AFTER 2 ======= TK 920

b) for failed tests:

 ======= BEFORE 1 ======= PK 0
 ======= AFTER 1 ======= PK 1000
 ======= BEFORE 1 ======= PK 958
 ======= BEFORE 1 ======= SK 956
 ======= AFTER 1 ======= PK 958
 ======= AFTER 1 ======= SK 956
 ======= BEFORE 2 ======= PK 930
 ======= BEFORE 2 ======= SK 928
 ======= BEFORE 2 ======= TK 930
 ======= AFTER 2 ======= PK 930
 ======= AFTER 2 ======= SK 928
 ======= AFTER 2 ======= TK 930

Optional (but very desirable):

• coredump
• backtrace
• netstat

[avtikhon]

Reproduced on 2.4.0-16-gcdf502c66

[ligurio]

reproduced on 23rd execution

======================================================================================
WORKR TEST                                            PARAMS          RESULT
---------------------------------------------------------------------------------
[001] engine/ddl.test.lua                             memtx           [ pass ]
[001] engine/ddl.test.lua                             vinyl           [ fail ]
[001] 
[001] Test failed! Result content mismatch:
[001] --- engine/ddl.result     Wed Mar 18 07:23:32 2020
[001] +++ engine/ddl.reject     Wed Mar 18 10:38:25 2020
[001] @@ -2463,7 +2463,7 @@
[001]  ...
[001]  box.space.test.index.pk:count() == box.space.test.index.sk:count()
[001]  ---
[001] -- true
[001] +- false
[001]  ...
[001]  box.space.test.index.pk:count() == box.space.test.index.tk:count()
[001]  ---
[001] @@ -2472,24 +2472,24 @@
[001]  inspector:cmd("restart server default")
[001]  box.space.test.index.pk:count() == box.space.test.index.sk:count()
[001]  ---
[001] +- false
[001] +...
[001] +box.space.test.index.pk:count() == box.space.test.index.tk:count()
[001] +---
[001]  - true
[001]  ...
[001] +box.snapshot()
[001] +---
[001] +- ok
[001] +...
[001] +box.space.test.index.pk:count() == box.space.test.index.sk:count()
[001] +---
[001] +- false
[001] +...
[001]  box.space.test.index.pk:count() == box.space.test.index.tk:count()
[001]  ---
[001]  - true
[001]  ...
[001] -box.snapshot()
[001] ----
[001] -- ok
[001] -...
[001] -box.space.test.index.pk:count() == box.space.test.index.sk:count()
[001] ----
[001] -- true
[001] -...
[001] -box.space.test.index.pk:count() == box.space.test.index.tk:count()
[001] ----
[001] -- true
[001] -...
[001]  box.space.test:drop()
[001]  ---
[001]  ...
[001] 
[001] Last 15 lines of Tarantool Log file [Instance "box"][/home/s.bronnikov/tarantool/build/test/var/001_
engine/box.log]:
[001] 2020-03-18 10:38:25.604 [8945] vinyl.dump.0/104/task I> writing `/home/s.bronnikov/tarantool/build/t
est/var/001_engine/box/599/0/00000000000000000275.index'
[001] 2020-03-18 10:38:25.636 [8945] main/107/vinyl.scheduler I> 599/0: dump completed
[001] 2020-03-18 10:38:25.636 [8945] main/107/vinyl.scheduler I> dumped 156864 bytes in 0.1 s, rate 1.4 MB/s
[001] 2020-03-18 10:38:25.640 [8945] main/120/console/unix/: I> vinyl checkpoint completed
[001] 2020-03-18 10:38:25.640 [8945] main/107/vinyl.scheduler I> 599/0: started compacting range (-inf..in
f), runs 4/4
[001] 2020-03-18 10:38:25.641 [8945] vinyl.compaction.0/102/task I> writing `/home/s.bronnikov/tarantool/b
uild/test/var/001_engine/box/599/0/00000000000000000277.run'
[001] 2020-03-18 10:38:25.692 [8945] vinyl.compaction.0/102/task I> writing `/home/s.bronnikov/tarantool/b
uild/test/var/001_engine/box/599/0/00000000000000000277.index'
[001] 2020-03-18 10:38:25.712 [8945] main I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine
/box/00000000000000003032.snap
[001] 2020-03-18 10:38:25.712 [8945] main I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine
/box/00000000000000002732.vylog
[001] 2020-03-18 10:38:25.722 [8945] main/104/gc I> removed /home/s.bronnikov/tarantool/build/test/var/001
_engine/box/599/0/00000000000000000247.index
[001] 2020-03-18 10:38:25.722 [8945] main/104/gc I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine/box/599/0/00000000000000000247.run
[001] 2020-03-18 10:38:25.722 [8945] main/104/gc I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine/box/599/0/00000000000000000249.index
[001] 2020-03-18 10:38:25.723 [8945] main/104/gc I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine/box/599/0/00000000000000000249.run
[001] 2020-03-18 10:38:25.723 [8945] wal I> removed /home/s.bronnikov/tarantool/build/test/var/001_engine/box/00000000000000003032.xlog
[001] 2020-03-18 10:38:25.760 [8945] main/107/vinyl.scheduler I> 599/0: completed compacting range (-inf..inf)
[Main process] Got failed test; gently terminate all workers...
[001] Worker "001_engine" got failed test; stopping the server...

Tarantool 2.4.0-101-g1f7e7aa2b
Target: Linux-x86_64-Debug
Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=ON
Compiler: /usr/bin/cc /usr/bin/c++
C_FLAGS: -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -fno-gnu89-inline -Wno-cast-function-type -Werror
CXX_FLAGS: -fexceptions -funwind-tables -fno-omit-frame-pointer -fno-stack-protector -fno-common -fopenmp -msse2 -std=c++11 -Wall -Wextra -Wno-strict-aliasing -Wno-char-subscripts -Wno-format-truncation -Wno-invalid-offsetof -Wno-cast-function-type -Werror

Command line:

for i in `seq 1 1 100`; do echo "$i XXXXXXXXXXXXXXXXX"; ../../test/test-run.py --builddir=/home/s.bronnikov/tarantool/build --vardir=/home/s.bronnikov/tarantool/build/test/var engine/ddl || break; done 2>&1 | tee ../../engine_ddl.log

Env: mcs1, CentOS Linux release 8.0.1905 (Core)

[ligurio]

https://lists.tarantool.org/pipermail/tarantool-patches/2020-April/015665.html

[avtikhon]

Seems that the issue still exists, fails occurred a few times in gitlab-ci, like this:
https://gitlab.com/tarantool/tarantool/-/jobs/553633335

 [091] --- engine/ddl.result	Thu May 14 16:12:09 2020
 [091] +++ engine/ddl.reject	Fri May 15 04:15:07 2020
 [091] @@ -2558,7 +2558,7 @@
 [091]  ...
 [091]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [091]  ---
 [091] -- true
 [091] +- false
 [091]  ...
 [091]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [091]  ---
 [091] @@ -2570,24 +2570,24 @@
 [091]  ...
 [091]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [091]  ---
 [091] +- false
 [091] +...
 [091] +inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [091] +---
 [091]  - true
 [091]  ...
 [091] +box.snapshot()
 [091] +---
 [091] +- ok
 [091] +...
 [091] +inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [091] +---
 [091] +- false
 [091] +...
 [091]  inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [091]  ---
 [091]  - true
 [091]  ...
 [091] -box.snapshot()
 [091] ----
 [091] -- ok
 [091] -...
 [091] -inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.sk:count() end)
 [091] ----
 [091] -- true
 [091] -...
 [091] -inspector:wait_cond(function() return box.space.test.index.pk:count() == box.space.test.index.tk:count() end)
 [091] ----
 [091] -- true
 [091] -...
 [091]  box.space.test:drop()
 [091]  ---
 [091]  ...