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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.4.3, 10.3.18, 10.4.9
Fix Version/s: 10.4.34, 10.5.25, 10.11.8, 10.6.18, 11.0.6, 11.1.5, 11.2.4, 11.4.2
Component/s: Galera, Tests
Labels:
- trx-versioning
Environment:
OS: CentOS Linux release 7.6.1810 (Core).

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.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

190215_desktop_stdout.log
2 kB
2019-02-15 14:37
190215_galera.versioning_trx_id.zip
308 kB
2019-02-15 14:37
191029_b2704_versioning_trx_id.zip
385 kB
2019-10-30 09:36
191029_HDD_versioning_trx_id.zip
1.27 MB
2019-10-30 09:36

Issue Links

blocks

MDEV-30172 Galera test case cleanup

Stalled

causes

MDEV-34313 WITHOUT_SERVER cannot compile mariadb-binlog

Closed

relates to

MDEV-18111 Galera 4: run galera test suite

Closed

Activity

Ascending order - Click to sort in descending order

Jan Lindström (Inactive) added a comment - 2019-03-27 14:15

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

Jan Lindström (Inactive) added a comment - 2019-03-27 14:15 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

Jan Lindström (Inactive) added a comment - 2019-04-01 05:31

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;

Jan Lindström (Inactive) added a comment - 2019-04-01 05:31 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(*) 0 +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;

Eugene Kosov (Inactive) added a comment - 2019-09-04 07:40

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

Eugene Kosov (Inactive) added a comment - 2019-09-04 07:40 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

Michael Widenius added a comment - 2019-10-15 12:04

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

Michael Widenius added a comment - 2019-10-15 12:04 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

Stepan Patryshev (Inactive) added a comment - 2019-10-30 09:37

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.

Stepan Patryshev (Inactive) added a comment - 2019-10-30 09:37 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 .

Stepan Patryshev (Inactive) added a comment - 2020-01-08 15:12

Increased the priority since it failed on Azure.

Stepan Patryshev (Inactive) added a comment - 2020-01-08 15:12 Increased the priority since it failed on Azure.

Stepan Patryshev (Inactive) added a comment - 2020-03-12 10:41

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.

Stepan Patryshev (Inactive) added a comment - 2020-03-12 10:41 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.

Seppo Jaakola added a comment - 2020-07-06 09:18

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?

Seppo Jaakola added a comment - 2020-07-06 09:18 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?

Stepan Patryshev (Inactive) added a comment - 2020-07-07 09:54

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

Stepan Patryshev (Inactive) added a comment - 2020-07-07 09:54 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

Jan Lindström (Inactive) added a comment - 2020-10-07 09:40

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

Jan Lindström (Inactive) added a comment - 2020-10-07 09:40 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

Aleksey Midenkov added a comment - 2022-02-21 22:57

Transactional versioning is low priority until new design.

Aleksey Midenkov added a comment - 2022-02-21 22:57 Transactional versioning is low priority until new design.

Jan Lindström added a comment - 2024-04-11 07:42

https://github.com/MariaDB/server/pull/3192

Jan Lindström added a comment - 2024-04-11 07:42 https://github.com/MariaDB/server/pull/3192

Julius Goryavsky added a comment - 2024-04-30 12:19

Fix merged with head revision: https://github.com/MariaDB/server/commit/136358036dfe2637b2db428b848148475ac21154

Julius Goryavsky added a comment - 2024-04-30 12:19 Fix merged with head revision: https://github.com/MariaDB/server/commit/136358036dfe2637b2db428b848148475ac21154

People

Assignee:: Julius Goryavsky

Reporter:: Stepan Patryshev (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 12 Start watching this issue

Dates

Created:: 2019-02-15 14:38

Updated:: 2024-06-26 00:21

Resolved:: 2024-04-30 12:19

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.