[MDEV-22195] galera_3nodes.galera_ipv6_mariabackup_section MTR failed: assert_grep.inc failed Created: 2020-04-08  Updated: 2023-04-04  Resolved: 2023-04-04

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Affects Version/s: 10.4.12, 10.8.0, 10.2.37, 10.3.28, 10.5.9, 10.6.0, 10.7.0, 10.9.0
Fix Version/s: 10.2.42, 10.3.33, 10.4.23, 10.5.14, 10.6.6, 10.7.2, 10.8.1, 10.9.1

Type: Bug Priority: Critical
Reporter: Stepan Patryshev (Inactive) Assignee: Julius Goryavsky
Resolution: Fixed Votes: 0
Labels: affects-tests
Environment:

rhel-8

Attachments: Text File 200407_rhel-8_galera_ipv6_mariabackup_section.log     File 200407_rhel-8_logs.tar.zip.001     File 200407_rhel-8_logs.tar.zip.002     File var.tar.gz    
Issue Links:
Relates
relates to MDEV-21770 `galera_3nodes.galera_ipv6_mariabacku... Closed
relates to MDEV-23574 galera_3nodes.galera_ipv6_mariabackup... Closed

 Description   

galera_3nodes.galera_ipv6_mariabackup_section failed on CI: "assert_grep.inc failed".

stdio:

10.4.12 65ca784b5d9aa0b545800ed5efca67e5415b5f4f

 
galera_3nodes.galera_ipv6_mariabackup_section 'innodb' w5 [ fail ]
 
        Test ended at 2020-04-07 07:10:00
 
 
 
CURRENT_TEST: galera_3nodes.galera_ipv6_mariabackup_section
 
mysqltest: In included file "./include/assert_grep.inc": 
included from /home/timofey_turenko_mariadb_com/MariaDBEnterprise/mysql-test/suite/galera_3nodes/t/galera_ipv6_mariabackup_section.test at line 72:
 
At line 152: assert_grep.inc failed.
 
 
 
The result from queries just before the failure was:
 
< snip >
 
connection node_2;
 
SET GLOBAL wsrep_provider_options='gmcast.isolate=0';
 
SELECT COUNT(*) = 1 FROM t1;
 
COUNT(*) = 1
 
1
 
DROP TABLE t1;
 
connection node_1;
 
include/assert_grep.inc [Streaming the backup to joiner at \[::1\]]
 
include/assert_grep.inc [async IST sender starting to serve tcp://\[::1\]:]
 
connection node_2;
 
include/assert_grep.inc [IST receiver addr using tcp://\[::1\]]
 
include/assert_grep.inc [Prepared IST receiver for 3-6, listening at: tcp://\[::1\]]
 
include/assert_grep.inc failed!
 
assert_text: 'Prepared IST receiver for 3-6, listening at: tcp://\[::1\]'
 
assert_file: '/var/tmp/mtr/5/log/mysqld.2.err'
 
assert_select: 'Prepared IST receiver for 3-6, listening at: tcp://\[::1\]'
 
assert_match: ''
 
assert_count: '1'
 
assert_only_after: 'CURRENT_TEST'
 
number of matching lines: 0
 
 
 
More results from queries before failure can be found in /var/tmp/mtr/5/log/galera_ipv6_mariabackup_section.log
 
 
 
 - saving '/var/tmp/mtr/5/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/' to '/var/tmp/mtr/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/'
 
 
 
Retrying test galera_3nodes.galera_ipv6_mariabackup_section, attempt(2/3)...

All other logs: vol1 and vol2.

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

It still fails on BB, 10.4.15.

Comment by Vladislav Lesin [ 2020-09-14 ]

Sometimes it fails with core dump with the following stack trace(10.5, commit hash 5f2728d5):

Thread 1 (Thread 0x7f15877fe700 (LWP 20230)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x00005572b51108fe in my_write_core (sig=6) at /home/vlesin/unencrypted/work/git/mariadb-server/mysys/stacktrace.c:424
 
#2  0x00005572b47c9b8c in handle_fatal_signal (sig=6) at /home/vlesin/unencrypted/work/git/mariadb-server/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007f1698a158b1 in __GI_abort () at abort.c:79
 
#6  0x00007f1698a0542a in __assert_fail_base (fmt=0x7f1698b8ca38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5572b581fdc9 "0", file=file@entry=0x5572b581fb98 "/home/vlesin/unencrypted/work/git/mariadb-server/wsrep-lib/src/server_state.cpp", line=line@entry=1368, function=function@entry=0x5572b5821a40 <wsrep::server_state::state(wsrep::unique_lock<wsrep::mutex>&, wsrep::server_state::state)::__PRETTY_FUNCTION__> "void wsrep::server_state::state(wsrep::unique_lock<wsrep::mutex>&, wsrep::server_state::state)") at assert.c:92
 
#7  0x00007f1698a054a2 in __GI___assert_fail (assertion=0x5572b581fdc9 "0", file=0x5572b581fb98 "/home/vlesin/unencrypted/work/git/mariadb-server/wsrep-lib/src/server_state.cpp", line=1368, function=0x5572b5821a40 <wsrep::server_state::state(wsrep::unique_lock<wsrep::mutex>&, wsrep::server_state::state)::__PRETTY_FUNCTION__> "void wsrep::server_state::state(wsrep::unique_lock<wsrep::mutex>&, wsrep::server_state::state)") at assert.c:101
 
#8  0x00005572b51ae4e8 in wsrep::server_state::state (this=0x5572b74e63b0, lock=..., state=wsrep::server_state::s_joined) at /home/vlesin/unencrypted/work/git/mariadb-server/wsrep-lib/src/server_state.cpp:1368
 
#9  0x00005572b51aaed5 in wsrep::server_state::sst_sent (this=0x5572b74e63b0, gtid=..., error=0) at /home/vlesin/unencrypted/work/git/mariadb-server/wsrep-lib/src/server_state.cpp:685
 
#10 0x00005572b4bf9283 in sst_donor_thread (a=0x7f1684b76b20) at /home/vlesin/unencrypted/work/git/mariadb-server/sql/wsrep_sst.cc:1731
 
#11 0x00005572b4b55235 in pfs_spawn_thread (arg=0x7f16700451b8) at /home/vlesin/unencrypted/work/git/mariadb-server/storage/perfschema/pfs.cc:2201
 
#12 0x00007f16999106db in start_thread (arg=0x7f15877fe700) at pthread_create.c:463
 
#13 0x00007f1698af6a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The state is the following:

./var/log/mysqld.1.err:4127:2020-09-14 18:09:09 0 [Warning] WSREP: server: node_1 unallowed state transition: joined -> joined

See var.tar.gz.

Comment by Vladislav Lesin [ 2020-09-16 ]

It does not look like mariabackup issue, because for some reason expected IST just does not happen in the test, while mariabackup is responsible for SST.

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

It failed also on BB, 10.5:

10.5.9 6a1e655cb0d400d8ed44fbfd22151b1d3e7f22d8

 
galera_3nodes.galera_ipv6_mariabackup 'innodb' w1 [ fail ]
 
        Test ended at 2020-12-02 13:59:24
 
 
 
CURRENT_TEST: galera_3nodes.galera_ipv6_mariabackup
 
 
 
 
 
Failed to start mysqld.2
 
mysqltest failed but provided no output
 
 
 
 
 
 - skipping '/dev/shm/var/1/log/galera_3nodes.galera_ipv6_mariabackup-innodb/'
 
 
 
Retrying test galera_3nodes.galera_ipv6_mariabackup, attempt(2/3)...
 
 
 
worker[1] > Restart  - not started
 
worker[1] > Restart  - not started
 
worker[1] > Restart  - not started
 
***Warnings generated in error logs during shutdown after running tests: galera_3nodes.galera_ipv6_mariabackup
 
 
 
WSREP_SST: [ERROR] /usr//bin/mariabackup finished with error: 1.  Check syslog or /dev/shm/var/1/mysqld.1/data//mariabackup.backup.log for details (20201202 13:59:24.338)
 
WSREP_SST: [ERROR] Cleanup after exit with status:22 (20201202 13:59:24.339)
 
2020-12-02 13:59:24 0 [ERROR] WSREP: Failed to read from: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16008/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/1/mysqld.1.sock' --datadir '/dev/shm/var/1/mysqld.1/data/' --defaults-file '/dev/shm/var/1/my.cnf' --defaults-group-suffix '.1' --gtid '7765d1b4-34d0-11eb-9ddd-e32c18734ad4:2' --gtid-domain-id '0' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/1/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
 
2020-12-02 13:59:24 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16008/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/1/mysqld.1.sock' --datadir '/dev/shm/var/1/mysqld.1/data/' --defaults-file '/dev/shm/var/1/my.cnf' --defaults-group-suffix '.1' --gtid '7765d1b4-34d0-11eb-9ddd-e32c18734ad4:2' --gtid-domain-id '0' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/1/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 22 (Invalid argument)
 
2020-12-02 13:59:24 0 [Warning] WSREP: server: node_1 unallowed state transition: connected -> joined
 
2020-12-02 13:59:24 0 [ERROR] WSREP: sst sent called when not SST donor, state CONNECTED
 
2020-12-02 13:59:24 0 [Warning] wsrep::sst_sent() returned an error: Not connected to Primary Component
 
2020-12-02 13:59:24 0 [ERROR] WSREP: Command did not run: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16008/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/1/mysqld.1.sock' --datadir '/dev/shm/var/1/mysqld.1/data/' --defaults-file '/dev/shm/var/1/my.cnf' --defaults-group-suffix '.1' --gtid '7765d1b4-34d0-11eb-9ddd-e32c18734ad4:2' --gtid-domain-id '0' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/1/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
 
WSREP_SST: [ERROR] xtrabackup_checkpoints missing, failed innobackupex/SST on donor (20201202 13:59:24.379)
 
WSREP_SST: [ERROR] Cleanup after exit with status:2 (20201202 13:59:24.381)
 
2020-12-02 13:59:24 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'joiner' --address '[::1]:16008' --datadir '/dev/shm/var/1/mysqld.2/data/' --defaults-file '/dev/shm/var/1/my.cnf' --defaults-group-suffix '.2' --parent '28951' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.2 --defaults-file=/dev/shm/var/1/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 2 (No such file or directory)
 
2020-12-02 13:59:24 0 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
 
2020-12-02 13:59:24 2 [ERROR] WSREP: Application received wrong state: 
2020-12-02 13:59:24 2 [ERROR] WSREP: Application state transfer failed. This is unrecoverable condition, restart required.

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

It failed also on BB 10.3.
stdio.log:

10.3.28 71806bf37c45d5490d8382cba6a5cca6879fa0db kvm-deb-bionic-amd64

 
galera_3nodes.galera_ipv6_mariabackup_section 'innodb' w2 [ fail ]
 
        Test ended at 2020-12-15 14:52:47
 
 
 
CURRENT_TEST: galera_3nodes.galera_ipv6_mariabackup_section
 
 
 
 
 
Failed to start mysqld.2
 
mysqltest failed but provided no output
 
 
 
 
 
 - saving '/dev/shm/var/2/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/' to '/dev/shm/var/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/'
 
 
 
Retrying test galera_3nodes.galera_ipv6_mariabackup_section, attempt(2/3)...
 
 
 
worker[2] > Restart  - not started
 
worker[2] > Restart  - not started
 
worker[2] > Restart  - not started
 
***Warnings generated in error logs during shutdown after running tests: galera_3nodes.galera_ipv6_mariabackup_section
 
 
 
WSREP_SST: [ERROR] /usr//bin/mariabackup finished with error: 1.  Check syslog or /dev/shm/var/2/mysqld.1/data//mariabackup.backup.log for details (20201215 14:52:39.785)
 
WSREP_SST: [ERROR] Cleanup after exit with status:22 (20201215 14:52:39.787)
 
2020-12-15 14:52:39 0 [ERROR] WSREP: Failed to read from: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16028/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/2/mysqld.1.sock' --datadir '/dev/shm/var/2/mysqld.1/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.1' --gtid '0f68914c-3f0f-11eb-a6c5-87188fa23c3f:0' --gtid-domain-id '0' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
 
2020-12-15 14:52:39 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16028/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/2/mysqld.1.sock' --datadir '/dev/shm/var/2/mysqld.1/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.1' --gtid '0f68914c-3f0f-11eb-a6c5-87188fa23c3f:0' --gtid-domain-id '0' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 22 (Invalid argument)
 
2020-12-15 14:52:39 0 [ERROR] WSREP: sst sent called when not SST donor, state CONNECTED
 
2020-12-15 14:52:39 0 [ERROR] WSREP: Command did not run: wsrep_sst_mariabackup --role 'donor' --address '[::1]:16028/xtrabackup_sst//1' --socket '/dev/shm/var/tmp/2/mysqld.1.sock' --datadir '/dev/shm/var/2/mysqld.1/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.1' --gtid '0f68914c-3f0f-11eb-a6c5-87188fa23c3f:0' --gtid-domain-id '0' --mysqld-args --defaults-group-suffix=.1 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300
 
WSREP_SST: [ERROR] xtrabackup_checkpoints missing, failed innobackupex/SST on donor (20201215 14:52:39.797)
 
WSREP_SST: [ERROR] Cleanup after exit with status:2 (20201215 14:52:39.799)
 
2020-12-15 14:52:39 0 [ERROR] WSREP: Process completed with error: wsrep_sst_mariabackup --role 'joiner' --address '[::1]:16028' --datadir '/dev/shm/var/2/mysqld.2/data/' --defaults-file '/dev/shm/var/2/my.cnf' --defaults-group-suffix '.2' --parent '27071' --binlog-index 'mysqld-bin.index' --mysqld-args --defaults-group-suffix=.2 --defaults-file=/dev/shm/var/2/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --core-file --loose-debug-sync-timeout=300: 2 (No such file or directory)
 
2020-12-15 14:52:39 0 [ERROR] WSREP: Failed to read uuid:seqno and wsrep_gtid_domain_id from joiner script.
 
2020-12-15 14:52:39 0 [ERROR] WSREP: SST failed: 2 (No such file or directory)
 
2020-12-15 14:52:39 0 [ERROR] Aborting
 
Warning: Memory not freed: 39488

Comment by Stepan Patryshev (Inactive) [ 2021-02-12 ]

It failed also on BB 10.2.
stdio.log:

10.2.37, 959dfac4d0e715725d05448a77c08d870d5aa247, kvm-deb-bionic-amd64

 
galera_3nodes.galera_ipv6_mariabackup_section 'innodb' w1 [ fail ]
 
        Test ended at 2021-01-19 10:32:52
 
 
 
CURRENT_TEST: galera_3nodes.galera_ipv6_mariabackup_section
 
 
 
 
 
Failed to start mysqld.2
 
mysqltest failed but provided no output
 
 
 
 
 
 - saving '/dev/shm/var/1/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/' to '/dev/shm/var/log/galera_3nodes.galera_ipv6_mariabackup_section-innodb/'
 
 
 
Retrying test galera_3nodes.galera_ipv6_mariabackup_section, attempt(2/3)...
 
 
 
worker[1] > Restart  - not started
 
worker[1] > Restart  - not started
 
worker[1] > Restart  - not started

Comment by Julius Goryavsky [ 2023-04-04 ]

Already fixed as part of https://jira.mariadb.org/browse/MDEV-24097 changes

Generated at Thu Feb 08 09:12:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.