[#MDEV-18590] galera.versioning_trx_id: Test failure: mysqltest: Result content mismatch

[MDEV-18590] galera.versioning_trx_id: Test failure: mysqltest: Result content mismatch Created: 2019-02-15 Updated: 2023-12-12
Status:	Stalled
Project:	MariaDB Server
Component/s:	Galera, Tests
Affects Version/s:	10.4.3, 10.3.18, 10.4.9
Fix Version/s:	10.4

Type:

Bug

Priority:

Critical

Reporter:

Stepan Patryshev (Inactive)

Assignee:

Aleksey Midenkov

Resolution:

Unresolved

Votes:

Labels:

trx-versioning

Environment:

OS: CentOS Linux release 7.6.1810 (Core).

Attachments:

190215_desktop_stdout.log

190215_galera.versioning_trx_id.zip

191029_HDD_versioning_trx_id.zip

191029_b2704_versioning_trx_id.zip

Issue Links:

Blocks
blocks	MDEV-30172	Galera test case cleanup	Stalled
Relates
relates to	~~MDEV-18111~~	Galera 4: run galera test suite	Closed

Description

MariaDB Server: 10.4.3-MariaDB-debug built from sources, branch=10.4, commit: c568e25379600db8af4bd39df4761ba0fbc1a14e.
Galera4 lib: debug built from sources, commit: 9cdbeb86c330b808571b14270e6428accb899c58.

Run:

./mtr galera.versioning_trx_id --force --max-test-fail=0 --repeat=3

./mtr --suite galera --force --big-test --max-test-fail=0

stdout.log: (the whole file is attached: 190215_desktop_stdout.log)

Completed: Failed 1/3 tests, 66.67% were successful.

CURRENT_TEST: galera.versioning_trx_id

--- /home/stepan/galera/git/10.4/server/mysql-test/suite/galera/r/versioning_trx_id.result	2019-01-23 13:59:37.220821400 +0200

+++ /home/stepan/galera/git/10.4/server/mysql-test/suite/galera/r/versioning_trx_id.reject	2019-02-15 15:38:57.358652400 +0200

@@ -48,7 +48,7 @@

 select count(*) from mysql.transaction_registry where begin_timestamp>=commit_timestamp;

 count(*)

-0

+1

 drop table t1;

 disconnect node_2;

 disconnect node_1;

mysqltest: Result content mismatch

See also attached 190215_galera.versioning_trx_id.zip.

Note: This test is failed sporadically.

Comments

Comment by Jan Lindström (Inactive) [ 2019-03-27 ]

Latest failure http://buildbot.askmonty.org/buildbot/builders/kvm-deb-bionic-amd64/builds/1757/steps/mtr-galera/logs/stdio

galera.versioning_trx_id 'innodb'        w2 [ fail ]  Found warnings/errors in server log file!

        Test ended at 2019-03-27 00:06:42

line

2019-03-27  0:06:37 1 [Warning] WSREP: Sending JOIN failed: -107 (Transport endpoint is not connected). Will retry in new primary component.

2019-03-27  0:06:37 1 [ERROR] WSREP: Failed to JOIN the cluster after SST

^ Found warnings in /dev/shm/var/2/log/mysqld.2.err

Comment by Jan Lindström (Inactive) [ 2019-04-01 ]

After some fixes:
http://buildbot.askmonty.org/buildbot/builders/kvm-zyp-sles150-amd64/builds/925/steps/mtr-galera/logs/stdio

galera.versioning_trx_id 'innodb'        w2 [ fail ]

        Test ended at 2019-03-30 07:16:16

CURRENT_TEST: galera.versioning_trx_id

--- /usr/share/mysql-test/suite/galera/r/versioning_trx_id.result	2019-03-29 22:07:55.000000000 +0000

+++ /dev/shm/var/2/log/versioning_trx_id.reject	2019-03-30 07:16:16.089542941 +0000

@@ -49,8 +49,13 @@

 select count(*) from mysql.transaction_registry where begin_timestamp='0-0-0';

 count(*)

+select * from mysql.transaction_registry;

+transaction_id	commit_id	begin_timestamp	commit_timestamp	isolation_level

+48	49	2019-03-30 07:16:15.974034	2019-03-30 07:16:15.975511	REPEATABLE-READ

+51	52	2019-03-30 07:16:16.029088	2019-03-30 07:16:15.000000	READ-COMMITTED

+54	55	2019-03-30 07:16:15.000000	2019-03-30 07:16:16.000000	READ-COMMITTED

 select count(*) from mysql.transaction_registry where begin_timestamp>=commit_timestamp;

 count(*)

-0

+1

 drop table t1;

 disconnect node_3;

Comment by Eugene Kosov (Inactive) [ 2019-09-04 ]

Initial message once again: http://buildbot.askmonty.org/buildbot/builders/kvm-deb-jessie-x86/builds/7215/steps/mtr-galera/logs/stdio

galera.versioning_trx_id 'innodb'        w1 [ fail ]  Found warnings/errors in server log file!

        Test ended at 2019-09-03 17:16:07

line

2019-09-03 17:16:01 2 [Warning] WSREP: Sending JOIN failed: -107 (Transport endpoint is not connected). Will retry in new primary component.

^ Found warnings in /dev/shm/var/1/log/mysqld.2.err

ok

 - saving '/dev/shm/var/1/log/galera.versioning_trx_id-innodb/' to '/dev/shm/var/log/galera.versioning_trx_id-innodb/'

Retrying test galera.versioning_trx_id, attempt(2/3)...

worker[1] > Restart  - not started

worker[1] > Restart  - not started

worker[1] > Restart  - not started

worker[1] > Restart  - not started

Comment by Michael Widenius [ 2019-10-15 ]

I just got the following failure in 10.3:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-xenial-x86/builds/13567/steps/mtr-galera/logs/stdio

galera.versioning_trx_id 'innodb' w2 [ fail ] Found warnings/errors in server log file!
Test ended at 2019-10-14 13:43:30
line
2019-10-14 13:43:23 0 [Warning] WSREP: Stray state UUID msg: 1e81d260-eeaa-11e9-9af7-5b436dd5f6e0 from node 1 (unspecified), current group state WAIT_STATE_UUID
^ Found warnings in /dev/shm/var/2/log/mysqld.3.err

Comment by Stepan Patryshev (Inactive) [ 2019-10-30 ]

It is sporadaically reproduced locally on 10.4.

10.4: 9afbb1069ab4178741b76adefacd3f6a0ed51369
191029 22:35:06 +26.762 galera.versioning_trx_id 'innodb' [ fail ]
Test ended at 2019-10-29 22:35:06

CURRENT_TEST: galera.versioning_trx_id
--- /home/stepan/mariadb/10.4/github/mysql-test/suite/galera/r/versioning_trx_id.result 2019-10-25 14:52:04.615763493 +0300
+++ /home/stepan/mariadb/10.4/github/mysql-test/suite/galera/r/versioning_trx_id.reject 2019-10-29 22:35:06.338698930 +0200
@@ -50,8 +50,13 @@
select count(*) from mysql.transaction_registry where begin_timestamp='0-0-0';
count(*)
0
+select * from mysql.transaction_registry;
+transaction_id commit_id begin_timestamp commit_timestamp isolation_level
+46 47 2019-10-29 22:35:04.541209 2019-10-29 22:35:04.550118 REPEATABLE-READ
+49 50 2019-10-29 22:35:05.031665 2019-10-29 22:35:04.000000 READ-COMMITTED
+52 53 2019-10-29 22:35:04.000000 2019-10-29 22:35:05.000000 READ-COMMITTED
select count(*) from mysql.transaction_registry where begin_timestamp>=commit_timestamp;
count(*)
-0
+1
drop table t1;
disconnect node_3;

mysqltest: Result length mismatch

Other logs: 191029_HDD_versioning_trx_id.zip.

And on bb also:

10.4: 576c96a9385f20cf4b6fe685e079dcf8
galera.versioning_trx_id 'innodb' w1 [ fail ] Found warnings/errors in server log file!
Test ended at 2019-10-29 16:30:11
line
2019-10-29 16:30:05 1 [Warning] WSREP: Sending JOIN failed: -107 (Transport endpoint is not connected). Will retry in new primary component.
2019-10-29 16:30:05 1 [ERROR] WSREP: Failed to JOIN the cluster after SST
^ Found warnings in /dev/shm/var/1/log/mysqld.2.err
ok

- saving '/dev/shm/var/1/log/galera.versioning_trx_id-innodb/' to '/dev/shm/var/log/galera.versioning_trx_id-innodb/'

Retrying test galera.versioning_trx_id, attempt(2/3)...

worker[1] > Restart - not started
worker[1] > Restart - not started
worker[1] > Restart - not started
worker[1] > Restart - not started

Other logs: 191029_b2704_versioning_trx_id.zip.

Comment by Stepan Patryshev (Inactive) [ 2020-01-08 ]

Increased the priority since it failed on Azure.

Comment by Stepan Patryshev (Inactive) [ 2020-03-12 ]

It is failed on bb on kvm-deb-jessie-x86.

stdio.log:

10.3.23 3c9bc0ce19c260401b4dd4c33273487829b29df5
galera.versioning_trx_id 'innodb' w1 [ fail ]
Test ended at 2020-03-11 11:28:28

CURRENT_TEST: galera.versioning_trx_id
--- /usr/share/mysql/mysql-test/suite/galera/r/versioning_trx_id.result 2020-03-11 09:11:15.000000000 -0400
+++ /dev/shm/var/1/log/versioning_trx_id.reject 2020-03-11 11:28:28.132888356 -0400
@@ -46,7 +46,7 @@
0
select count(*) from mysql.transaction_registry where begin_timestamp>=commit_timestamp;
count(*)
-0
+1
drop table t1;
disconnect node_2;
disconnect node_1;

mysqltest: Result content mismatch

- saving '/dev/shm/var/1/log/galera.versioning_trx_id-innodb/' to '/dev/shm/var/log/galera.versioning_trx_id-innodb/'

Retrying test galera.versioning_trx_id, attempt(2/3)...

worker[1] > Restart - not started
worker[1] > Restart - not started
worker[1] > Restart - not started
worker[1] > Restart - not started

And currently it is disabled only on CS/ES 10.4, and enabled on CS/ES 10.2/10.3.

Comment by Seppo Jaakola [ 2020-07-06 ]

I wonder if this test has valid scenario, in the first place. What is the actual feature requirement of system versioned tables in Galera cluster, that this test is trying to enforce? Should this test pass also if Galera replication is replaced by async replication?

Comment by Stepan Patryshev (Inactive) [ 2020-07-07 ]

It is still failed on BB: https://mdbe-ci-repo.mariadb.net/bb-logs/MariaDBServerCommunity/10.3-2020-Jun-21-10-00-00/rhel/8/mtr-galera-test/mtr.log

Comment by Jan Lindström (Inactive) [ 2020-10-07 ]

kevg I have some questions on this test case:

What this test is trying to enforce ?
Have you tested this case using async replication?
When/Where exactly those begin_timestamp and commit_timestamp are computed ?
Writes to mysql.transaction_registry are not replicated by Galera
Above could mean that those timestamps on mysql.transaction_registry are computed on every node or not at all depending where the computation is
I'm not familiar with system versioned tables implementation

Comment by Aleksey Midenkov [ 2022-02-21 ]

Transactional versioning is low priority until new design.

Generated at Thu Feb 08 08:45:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.

[MDEV-18590] galera.versioning_trx_id: Test failure: mysqltest: Result content mismatch Created: 2019-02-15 Updated: 2023-12-12