From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp42.i.mail.ru (smtp42.i.mail.ru [94.100.177.102]) (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 68E4245C305 for ; Tue, 8 Dec 2020 18:49:28 +0300 (MSK) From: "Alexander V. Tikhonov" Date: Tue, 8 Dec 2020 18:49:25 +0300 Message-Id: <58584e4677c66eb40e7ea504382df39be2d5ffef.1607442267.git.avtikhon@tarantool.org> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [Tarantool-patches] [PATCH v1] test: move error messages into logs List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Kirill Yukhin Cc: tarantool-patches@dev.tarantool.org Cc: tarantool-patches@dev.tarantool.org Found that some tests on fail use box.info* calls to print information, like: [024] --- replication/wal_rw_stress.result Mon Nov 30 10:02:43 2020 [024] +++ var/rejects/replication/wal_rw_stress.reject Sun Dec 6 16:06:46 2020 [024] @@ -77,7 +77,45 @@ [024] r.downstream.status ~= 'stopped') \ [024] end) or box.info [024] --- [024] -- true [024] +- version: 2.7.0-109-g0b3ad5d8a0 [024] + id: 2 [024] + ro: false [024] + uuid: e0b8863f-7b50-4eb5-947f-77f92c491827 It denies test-run from rerunng these tests using checksums, because of changing output on each fail, like 'version:' either 'uuid:' fields values above. To avoid of it, these calls outputs should be redirected to log files using log.error(). Also the same fix made for tests with fio.listdir() and fio.stat() on errors. --- Github: https://github.com/tarantool/tarantool/tree/avtikhon/tests-output-to-logs test/app/fio.result | 7 ++-- test/app/fio.test.lua | 5 +-- test/replication/gc.result | 35 ++++++++++--------- test/replication/gc.test.lua | 33 ++++++++--------- .../gh-5195-qsync-replica-write.result | 2 +- .../gh-5195-qsync-replica-write.test.lua | 2 +- test/replication/status.result | 2 +- test/replication/status.test.lua | 2 +- test/replication/suite.ini | 2 +- test/replication/wal_rw_stress.result | 2 +- test/replication/wal_rw_stress.test.lua | 2 +- 11 files changed, 51 insertions(+), 43 deletions(-) diff --git a/test/app/fio.result b/test/app/fio.result index 8a08755a2..20cfe345d 100644 --- a/test/app/fio.result +++ b/test/app/fio.result @@ -10,6 +10,9 @@ fiber = require 'fiber' buffer = require 'buffer' --- ... +log = require 'log' +--- +... test_run = require('test_run').new() --- ... @@ -1553,11 +1556,11 @@ os.setenv('TMPDIR', tmpdir) dir = fio.tempdir() --- ... -dir:startswith(tmpdir) or {dir, tmpdir} +dir:startswith(tmpdir) or log.error({dir, tmpdir}) --- - true ... -fio.stat(dir) ~= nil or fio.stat(dir) +fio.stat(dir) ~= nil or log.error(fio.stat(dir)) --- - true ... diff --git a/test/app/fio.test.lua b/test/app/fio.test.lua index 92ba3ff20..d1a20e8e5 100644 --- a/test/app/fio.test.lua +++ b/test/app/fio.test.lua @@ -2,6 +2,7 @@ fio = require 'fio' ffi = require 'ffi' fiber = require 'fiber' buffer = require 'buffer' +log = require 'log' test_run = require('test_run').new() -- umask @@ -508,8 +509,8 @@ tmpdir = cwd..'/tmp-.dot.-' fio.mkdir(tmpdir) os.setenv('TMPDIR', tmpdir) dir = fio.tempdir() -dir:startswith(tmpdir) or {dir, tmpdir} -fio.stat(dir) ~= nil or fio.stat(dir) +dir:startswith(tmpdir) or log.error({dir, tmpdir}) +fio.stat(dir) ~= nil or log.error(fio.stat(dir)) tmpdir = cwd..'/tmp2' os.setenv('TMPDIR', tmpdir) diff --git a/test/replication/gc.result b/test/replication/gc.result index 050a6100c..0c79484b7 100644 --- a/test/replication/gc.result +++ b/test/replication/gc.result @@ -13,6 +13,9 @@ fiber = require('fiber') fio = require('fio') --- ... +log = require('log') +--- +... test_run:cleanup_cluster() --- ... @@ -131,11 +134,11 @@ test_run:cmd("switch default") ... -- Check that garbage collection removed the snapshot once -- the replica released the corresponding checkpoint. -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(1) or fio.listdir('./master') -- Make sure the replica will not receive data until +wait_xlog(1) or log.error(fio.listdir('./master')) -- Make sure the replica will not receive data until --- - true ... @@ -168,11 +171,11 @@ box.snapshot() --- - ok ... -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(2) or fio.listdir('./master') +wait_xlog(2) or log.error(fio.listdir('./master')) --- - true ... @@ -201,11 +204,11 @@ test_run:cmd("switch default") ... -- Now garbage collection should resume and delete files left -- from the old checkpoint. -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(0) or fio.listdir('./master') +wait_xlog(0) or log.error(fio.listdir('./master')) --- - true ... @@ -244,11 +247,11 @@ fiber.sleep(0.1) -- wait for master to relay data -- Garbage collection must not delete the old xlog file -- because it is still needed by the replica, but remove -- the old snapshot. -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(2) or fio.listdir('./master') +wait_xlog(2) or log.error(fio.listdir('./master')) --- - true ... @@ -282,11 +285,11 @@ test_run:cmd("switch default") - true ... -- Now it's safe to drop the old xlog. -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(1) or fio.listdir('./master') +wait_xlog(1) or log.error(fio.listdir('./master')) --- - true ... @@ -318,11 +321,11 @@ box.snapshot() --- - ok ... -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(2) or fio.listdir('./master') +wait_xlog(2) or log.error(fio.listdir('./master')) --- - true ... @@ -331,11 +334,11 @@ wait_xlog(2) or fio.listdir('./master') test_run:cleanup_cluster() --- ... -wait_gc(1) or box.info.gc() +wait_gc(1) or log.error(box.info.gc()) --- - true ... -wait_xlog(1) or fio.listdir('./master') +wait_xlog(1) or log.error(fio.listdir('./master')) --- - true ... @@ -423,7 +426,7 @@ box.snapshot() --- - ok ... -wait_xlog(3) or fio.listdir('./master') +wait_xlog(3) or log.error(fio.listdir('./master')) --- - true ... @@ -436,7 +439,7 @@ box.snapshot() --- - ok ... -wait_xlog(0, 10) or fio.listdir('./master') +wait_xlog(0, 10) or log.error(fio.listdir('./master')) --- - true ... diff --git a/test/replication/gc.test.lua b/test/replication/gc.test.lua index 7cd18402c..a0588719a 100644 --- a/test/replication/gc.test.lua +++ b/test/replication/gc.test.lua @@ -3,6 +3,7 @@ engine = test_run:get_cfg('engine') replica_set = require('fast_replica') fiber = require('fiber') fio = require('fio') +log = require('log') test_run:cleanup_cluster() test_run:cmd("create server replica with rpl_master=default, script='replication/replica.lua'") @@ -69,8 +70,8 @@ test_run:cmd("switch default") -- Check that garbage collection removed the snapshot once -- the replica released the corresponding checkpoint. -wait_gc(1) or box.info.gc() -wait_xlog(1) or fio.listdir('./master') -- Make sure the replica will not receive data until +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(1) or log.error(fio.listdir('./master')) -- Make sure the replica will not receive data until -- we test garbage collection. box.error.injection.set("ERRINJ_RELAY_SEND_DELAY", true) @@ -86,8 +87,8 @@ box.snapshot() -- Invoke garbage collection. Check that it doesn't remove -- xlogs needed by the replica. box.snapshot() -wait_gc(1) or box.info.gc() -wait_xlog(2) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(2) or log.error(fio.listdir('./master')) -- Resume replication so that the replica catches -- up quickly. @@ -101,8 +102,8 @@ test_run:cmd("switch default") -- Now garbage collection should resume and delete files left -- from the old checkpoint. -wait_gc(1) or box.info.gc() -wait_xlog(0) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(0) or log.error(fio.listdir('./master')) -- -- Check that the master doesn't delete xlog files sent to the -- replica until it receives a confirmation that the data has @@ -120,8 +121,8 @@ fiber.sleep(0.1) -- wait for master to relay data -- Garbage collection must not delete the old xlog file -- because it is still needed by the replica, but remove -- the old snapshot. -wait_gc(1) or box.info.gc() -wait_xlog(2) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(2) or log.error(fio.listdir('./master')) -- Imitate the replica crash and, then, wake up. -- Just 'stop server replica' (SIGTERM) is not sufficient to stop -- a tarantool instance when ERRINJ_WAL_DELAY is set, because @@ -134,8 +135,8 @@ test_run:wait_cond(function() return box.space.test:count() == 310 end, 10) box.space.test:count() test_run:cmd("switch default") -- Now it's safe to drop the old xlog. -wait_gc(1) or box.info.gc() -wait_xlog(1) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(1) or log.error(fio.listdir('./master')) -- Stop the replica. test_run:cmd("stop server replica") test_run:cmd("cleanup server replica") @@ -149,14 +150,14 @@ _ = s:auto_increment{} box.snapshot() _ = s:auto_increment{} box.snapshot() -wait_gc(1) or box.info.gc() -wait_xlog(2) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(2) or log.error(fio.listdir('./master')) -- The xlog should only be deleted after the replica -- is unregistered. test_run:cleanup_cluster() -wait_gc(1) or box.info.gc() -wait_xlog(1) or fio.listdir('./master') +wait_gc(1) or log.error(box.info.gc()) +wait_xlog(1) or log.error(fio.listdir('./master')) -- -- Test that concurrent invocation of the garbage collector works fine. -- @@ -195,13 +196,13 @@ _ = s:auto_increment{} box.snapshot() _ = s:auto_increment{} box.snapshot() -wait_xlog(3) or fio.listdir('./master') +wait_xlog(3) or log.error(fio.listdir('./master')) -- Delete the replica from the cluster table and check that -- all xlog files are removed. test_run:cleanup_cluster() box.snapshot() -wait_xlog(0, 10) or fio.listdir('./master') +wait_xlog(0, 10) or log.error(fio.listdir('./master')) -- Restore the config. box.cfg{replication = {}} diff --git a/test/replication/gh-5195-qsync-replica-write.result b/test/replication/gh-5195-qsync-replica-write.result index 906f4910d..85e00e6ed 100644 --- a/test/replication/gh-5195-qsync-replica-write.result +++ b/test/replication/gh-5195-qsync-replica-write.result @@ -99,7 +99,7 @@ test_run:wait_cond(function() local vclock = box.info.replication[replica_id].downstream.vclock \ return (vclock and vclock[replica_id] and \ vclock[replica_id] >= replica_lsn) \ - end) or box.info + end) or require('log').error(box.info) | --- | - true | ... diff --git a/test/replication/gh-5195-qsync-replica-write.test.lua b/test/replication/gh-5195-qsync-replica-write.test.lua index d7d09fa35..64c48be99 100644 --- a/test/replication/gh-5195-qsync-replica-write.test.lua +++ b/test/replication/gh-5195-qsync-replica-write.test.lua @@ -44,7 +44,7 @@ test_run:wait_cond(function() local vclock = box.info.replication[replica_id].downstream.vclock \ return (vclock and vclock[replica_id] and \ vclock[replica_id] >= replica_lsn) \ - end) or box.info + end) or require('log').error(box.info) box.cfg{replication_synchro_quorum = 2} test_run:wait_cond(function() return f:status() == 'dead' end) diff --git a/test/replication/status.result b/test/replication/status.result index 4f2cf56ea..a8c515dbb 100644 --- a/test/replication/status.result +++ b/test/replication/status.result @@ -182,7 +182,7 @@ test_run:wait_cond(function() \ return (r ~= nil and box.info.vclock ~= nil and \ r[master_id] == box.info.vclock[master_id] and \ r[replica_id] == box.info.vclock[replica_id]) \ - end) or box.info + end) or require('log').error(box.info) --- - true ... diff --git a/test/replication/status.test.lua b/test/replication/status.test.lua index 0facd7c0a..431463d8a 100644 --- a/test/replication/status.test.lua +++ b/test/replication/status.test.lua @@ -71,7 +71,7 @@ test_run:wait_cond(function() \ return (r ~= nil and box.info.vclock ~= nil and \ r[master_id] == box.info.vclock[master_id] and \ r[replica_id] == box.info.vclock[replica_id]) \ - end) or box.info + end) or require('log').error(box.info) -- -- Replica diff --git a/test/replication/suite.ini b/test/replication/suite.ini index 6c9eccb7a..156ed5c56 100644 --- a/test/replication/suite.ini +++ b/test/replication/suite.ini @@ -140,7 +140,7 @@ fragile = { }, "gc.test.lua": { "issues": [ "gh-5474" ], - "checksums": [ "eba8a4dd4110f26e5189c24f117a1679" ] + "checksums": [ "b71b49a2066375eab34891f82c1ea013", "ba5a30981d31d060be39a3880422f915", "641731a65ba65c6bbd32437a45ca55d3" ] }, "bootstrap_leader.test.lua": { "issues": [ "gh-5478" ], diff --git a/test/replication/wal_rw_stress.result b/test/replication/wal_rw_stress.result index 41f307fc2..7abb7279b 100644 --- a/test/replication/wal_rw_stress.result +++ b/test/replication/wal_rw_stress.result @@ -75,7 +75,7 @@ test_run:wait_cond(function() \ local r = box.info.replication[1] \ return (r ~= nil and r.downstream ~= nil and \ r.downstream.status ~= 'stopped') \ -end) or box.info +end) or require('log').error(box.info) --- - true ... diff --git a/test/replication/wal_rw_stress.test.lua b/test/replication/wal_rw_stress.test.lua index 96df2d6bf..9d0748cfa 100644 --- a/test/replication/wal_rw_stress.test.lua +++ b/test/replication/wal_rw_stress.test.lua @@ -42,7 +42,7 @@ test_run:wait_cond(function() \ local r = box.info.replication[1] \ return (r ~= nil and r.downstream ~= nil and \ r.downstream.status ~= 'stopped') \ -end) or box.info +end) or require('log').error(box.info) test_run:cmd("switch default") -- Cleanup. -- 2.25.1