* [Tarantool-patches] [PATCH v1] test: move error messages into logs
@ 2020-12-08 15:49 Alexander V. Tikhonov
2020-12-10 14:44 ` Kirill Yukhin
0 siblings, 1 reply; 2+ messages in thread
From: Alexander V. Tikhonov @ 2020-12-08 15:49 UTC (permalink / raw)
To: Kirill Yukhin; +Cc: tarantool-patches
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
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: [Tarantool-patches] [PATCH v1] test: move error messages into logs
2020-12-08 15:49 [Tarantool-patches] [PATCH v1] test: move error messages into logs Alexander V. Tikhonov
@ 2020-12-10 14:44 ` Kirill Yukhin
0 siblings, 0 replies; 2+ messages in thread
From: Kirill Yukhin @ 2020-12-10 14:44 UTC (permalink / raw)
To: Alexander V. Tikhonov; +Cc: tarantool-patches
Hello,
On 08 Dec 18:49, Alexander V. Tikhonov wrote:
> 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
I've checked your patch into 1.10, 2.5, 2.6 and master.
--
Regards, Kirill Yukhin
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2020-12-10 14:44 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-12-08 15:49 [Tarantool-patches] [PATCH v1] test: move error messages into logs Alexander V. Tikhonov
2020-12-10 14:44 ` Kirill Yukhin
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox