[Maria-discuss] for years failing tests
shouldn't the testsuite at some point in time run without errors? "run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts [root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --mysqld=--binlog-format=mixed --force' mysql rm -rf /usr/share/mysql-test/var/* rpl.rpl_binlog_index 'row' [ fail ] Test ended at 2017-01-20 16:56:16 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' rpl.sec_behind_master-5114 'stmt' [ fail ] Test ended at 2017-01-20 16:58:33 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' [ fail ] Test ended at 2017-01-20 16:59:24 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
Hi, Reindl! I cannot repeat this. I get: rpl.rpl_binlog_index 'row' [ skipped ] Not ROW format rpl.sec_behind_master-5114 'stmt' [ skipped ] Not STATEMENT format rpl.rpl_semi_sync_event_after_sync 'innodb,mix' [ pass ] 10470 (it's innodb in my build, but that shouldn't matter). The first two tests should not even be started, because you run your tests with --mysqld=--binlog-format=mixed, so mysql-test-run.pl will skip tests with 'row' and 'stmt' without executing a single line from them. I don't know what can possibly go wrong for this functionality not to work. It doesn't depend on replication, it doesn't depend on the server or build options, it's just loading the combination file and skipping combinations that don't match the specified command-line option. I've never seen it misbehaving. On Jan 20, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors? "run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
[root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --mysqld=--binlog-format=mixed --force' mysql rm -rf /usr/share/mysql-test/var/*
rpl.rpl_binlog_index 'row' [ fail ] Test ended at 2017-01-20 16:56:16 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/'
rpl.sec_behind_master-5114 'stmt' [ fail ] Test ended at 2017-01-20 16:58:33 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' [ fail ] Test ended at 2017-01-20 16:59:24 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
Regards, Sergei Chief Architect MariaDB and security@mariadb.org
Am 20.01.2017 um 17:21 schrieb Sergei Golubchik:
Hi, Reindl!
I cannot repeat this. I get:
rpl.rpl_binlog_index 'row' [ skipped ] Not ROW format rpl.sec_behind_master-5114 'stmt' [ skipped ] Not STATEMENT format rpl.rpl_semi_sync_event_after_sync 'innodb,mix' [ pass ] 10470
they are failing here for many years see alo the mess about enrcytion - instead realize "oh, it's not there" which happens at begin at llops through all tests, all of them failing and waits each time some seconds _______________________________ something similar happend when you built without partition support as my changelog of the rpm package shows [root@srv-rhsoft:~]$ rpm -q --changelog mariadb-server | grep -i partition - enable partition because too much auto-test problems _______________________________ encryption.innodb_encryption 'xtradb' [ skipped ] Test requires InnoDB. 2017-01-20 17:09:37 140411189942592 [ERROR] InnoDB: cannot enable encryption, encryption plugin is not available 2017-01-20 17:09:37 140411189942592 [ERROR] Plugin 'InnoDB' init function returned error. 2017-01-20 17:09:37 140411189942592 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 9910, winpid: 9910, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.tempfiles 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 17:10:27 CURRENT_TEST: encryption.tempfiles Failed to start mysqld.1 mysqltest failed but provided no output - saving '/usr/share/mysql-test/var/log/encryption.tempfiles-cbc,xtradb/' to '/usr/share/mysql-test/var/log/encryption.tempfiles-cbc,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.tempfiles 2017-01-20 17:10:25 140290260609344 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 17:10:25 140290260609344 [ERROR] Aborting worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 9933, winpid: 9933, exit: 1792] died after mysql-test-run waited 3.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.tempfiles 'ctr,xtradb' [ fail ] Test ended at 2017-01-20 17:10:31 CURRENT_TEST: encryption.tempfiles CURRENT_TEST: encryption.tempfiles Failed to start mysqld.1 - saving '/usr/share/mysql-test/var/log/encryption.tempfiles-ctr,xtradb/' to '/usr/share/mysql-test/var/log/encryption.tempfiles-ctr,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.tempfiles 2017-01-20 17:10:28 139721608362304 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_ctr' 2017-01-20 17:10:28 139721608362304 [ERROR] Aborting encryption.innodb-page_encryption-32k 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 17:12:57 CURRENT_TEST: encryption.innodb-page_encryption-32k Failed to start mysqld.1 mysqltest failed but provided no output - saving '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-32k-cbc,xtradb/' to '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-32k-cbc,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption-32k 2017-01-20 17:12:55 140523870546240 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 17:12:55 140523870546240 [ERROR] Aborting worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 12568, winpid: 12568, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb-page_encryption-32k 'ctr,xtradb' [ fail ] Test ended at 2017-01-20 17:13:01 CURRENT_TEST: encryption.innodb-page_encryption-32k CURRENT_TEST: encryption.innodb-page_encryption-32k Failed to start mysqld.1
(it's innodb in my build, but that shouldn't matter). The first two tests should not even be started, because you run your tests with --mysqld=--binlog-format=mixed, so mysql-test-run.pl will skip tests with 'row' and 'stmt' without executing a single line from them. I don't know what can possibly go wrong for this functionality not to work. It doesn't depend on replication, it doesn't depend on the server or build options, it's just loading the combination file and skipping combinations that don't match the specified command-line option. I've never seen it misbehaving.
On Jan 20, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors? "run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
[root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --mysqld=--binlog-format=mixed --force' mysql rm -rf /usr/share/mysql-test/var/*
rpl.rpl_binlog_index 'row' [ fail ] Test ended at 2017-01-20 16:56:16 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/'
rpl.sec_behind_master-5114 'stmt' [ fail ] Test ended at 2017-01-20 16:58:33 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' [ fail ] Test ended at 2017-01-20 16:59:24 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
Regards, Sergei Chief Architect MariaDB and security@mariadb.org
-- Reindl Harald the lounge interactive design GmbH A-1060 Vienna, Hofmühlgasse 17 CTO / CISO / Software-Development m: +43 676 40 221 40 p: +43 1 595 3999 33 http://www.thelounge.net/
looks like many of them are caused by "--mysqld=--binlog-format=mixed" but without a ton of tests are skipped with "Neither MIXED nor STATEMENT binlog format" what i really don't understand when you configure and start mysqld scripted binlog.binlog_mysqlbinlog-cp932 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_query_filter_rules 'row' [ pass ] 32 binlog.binlog_mysqlbinlog_row 'row' [ pass ] 132 binlog.binlog_mysqlbinlog_row_myisam 'row' [ pass ] 100 binlog.binlog_row_ctype_ucs 'row' [ pass ] 46 binlog.binlog_row_insert_select 'row' [ pass ] 64 binlog.binlog_row_mysqlbinlog_options 'row' [ pass ] 37 binlog.binlog_stm_ctype_ucs 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_stm_insert_select 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_stm_row 'row' [ pass ] 241 binlog.binlog_tmp_table 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format main.ctype_cp932_binlog_row [ pass ] 39 binlog.binlog_drop_if_exists 'row' [ pass ] 111 binlog.binlog_grant 'row' [ pass ] 6 binlog.binlog_max_extension 'row' [ pass ] 2830 binlog.binlog_mdev717 'row' [ skipped ] debug_sync is not available binlog.binlog_mysqlbinlog2 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_mysqlbinlog_base64 'row' [ pass ] 139 binlog.binlog_row_ctype_cp932 'row' [ pass ] 219 binlog.binlog_row_drop_tbl 'row' [ pass ] 23 binlog.binlog_row_drop_tmp_tbl 'row' [ pass ] 160 binlog.binlog_row_mysqlbinlog_verbose 'row' [ pass ] 26 binlog.binlog_server_id 'row' [ pass ] 16 binlog.binlog_sql_mode 'row' [ pass ] 46 binlog.binlog_start_comment 'row' [ pass ] 25 binlog.binlog_stm_ctype_cp932 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_stm_drop_tbl 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format binlog.binlog_stm_drop_tmp_tbl 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format Am 20.01.2017 um 17:37 schrieb Reindl Harald:
Am 20.01.2017 um 17:21 schrieb Sergei Golubchik:
Hi, Reindl!
I cannot repeat this. I get:
rpl.rpl_binlog_index 'row' [ skipped ] Not ROW format rpl.sec_behind_master-5114 'stmt' [ skipped ] Not STATEMENT format rpl.rpl_semi_sync_event_after_sync 'innodb,mix' [ pass ] 10470
they are failing here for many years
see alo the mess about enrcytion - instead realize "oh, it's not there" which happens at begin at llops through all tests, all of them failing and waits each time some seconds _______________________________
something similar happend when you built without partition support as my changelog of the rpm package shows
[root@srv-rhsoft:~]$ rpm -q --changelog mariadb-server | grep -i partition - enable partition because too much auto-test problems _______________________________
encryption.innodb_encryption 'xtradb' [ skipped ] Test requires InnoDB. 2017-01-20 17:09:37 140411189942592 [ERROR] InnoDB: cannot enable encryption, encryption plugin is not available 2017-01-20 17:09:37 140411189942592 [ERROR] Plugin 'InnoDB' init function returned error. 2017-01-20 17:09:37 140411189942592 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 9910, winpid: 9910, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.tempfiles 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 17:10:27
CURRENT_TEST: encryption.tempfiles
Failed to start mysqld.1 mysqltest failed but provided no output
- saving '/usr/share/mysql-test/var/log/encryption.tempfiles-cbc,xtradb/' to '/usr/share/mysql-test/var/log/encryption.tempfiles-cbc,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.tempfiles
2017-01-20 17:10:25 140290260609344 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 17:10:25 140290260609344 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 9933, winpid: 9933, exit: 1792] died after mysql-test-run waited 3.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.tempfiles 'ctr,xtradb' [ fail ] Test ended at 2017-01-20 17:10:31
CURRENT_TEST: encryption.tempfiles CURRENT_TEST: encryption.tempfiles
Failed to start mysqld.1
- saving '/usr/share/mysql-test/var/log/encryption.tempfiles-ctr,xtradb/' to '/usr/share/mysql-test/var/log/encryption.tempfiles-ctr,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.tempfiles
2017-01-20 17:10:28 139721608362304 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_ctr' 2017-01-20 17:10:28 139721608362304 [ERROR] Aborting
encryption.innodb-page_encryption-32k 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 17:12:57
CURRENT_TEST: encryption.innodb-page_encryption-32k
Failed to start mysqld.1 mysqltest failed but provided no output
- saving '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-32k-cbc,xtradb/' to '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-32k-cbc,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption-32k
2017-01-20 17:12:55 140523870546240 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 17:12:55 140523870546240 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 12568, winpid: 12568, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb-page_encryption-32k 'ctr,xtradb' [ fail ] Test ended at 2017-01-20 17:13:01
CURRENT_TEST: encryption.innodb-page_encryption-32k CURRENT_TEST: encryption.innodb-page_encryption-32k
Failed to start mysqld.1
(it's innodb in my build, but that shouldn't matter). The first two tests should not even be started, because you run your tests with --mysqld=--binlog-format=mixed, so mysql-test-run.pl will skip tests with 'row' and 'stmt' without executing a single line from them. I don't know what can possibly go wrong for this functionality not to work. It doesn't depend on replication, it doesn't depend on the server or build options, it's just loading the combination file and skipping combinations that don't match the specified command-line option. I've never seen it misbehaving.
On Jan 20, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors? "run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
[root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --mysqld=--binlog-format=mixed --force' mysql rm -rf /usr/share/mysql-test/var/*
rpl.rpl_binlog_index 'row' [ fail ] Test ended at 2017-01-20 16:56:16 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/'
rpl.sec_behind_master-5114 'stmt' [ fail ] Test ended at 2017-01-20 16:58:33 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' [ fail ] Test ended at 2017-01-20 16:59:24 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
Hi, Reindl! On Jan 20, Reindl Harald wrote:
looks like many of them are caused by "--mysqld=--binlog-format=mixed" but without a ton of tests are skipped with "Neither MIXED nor STATEMENT binlog format" what i really don't understand when you configure and start mysqld scripted
binlog.binlog_mysqlbinlog-cp932 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format
Okay, that's what I actually suspected after your first email, when 'row' and 'stmt' combinations weren't skipped as the should've been. Our mysql-test-run.pl does not skip tests with this message. It used to, in MySQL times, but I've changed that many years ago. MySQL's mysql-test-run.pl still has this behavior. You're using MySQL's mysql-test-run.pl with our tests. Regards, Sergei Chief Architect MariaDB and security@mariadb.org
Am 20.01.2017 um 20:26 schrieb Sergei Golubchik:
Hi, Reindl!
On Jan 20, Reindl Harald wrote:
looks like many of them are caused by "--mysqld=--binlog-format=mixed" but without a ton of tests are skipped with "Neither MIXED nor STATEMENT binlog format" what i really don't understand when you configure and start mysqld scripted
binlog.binlog_mysqlbinlog-cp932 'row' [ skipped ] Neither MIXED nor STATEMENT binlog format
Okay, that's what I actually suspected after your first email, when 'row' and 'stmt' combinations weren't skipped as the should've been.
Our mysql-test-run.pl does not skip tests with this message. It used to, in MySQL times, but I've changed that many years ago.
MySQL's mysql-test-run.pl still has this behavior.
You're using MySQL's mysql-test-run.pl with our tests
are you kidding me? [root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --force' mysql rm -rf /usr/share/mysql-test/var/* [root@testserver:~]$ rpm -q --file /usr/share/mysql-test mariadb-test-10.1.21-3.fc24.20170120.rh.x86_64
Hi Reindl, On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with. Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up.
[root@testserver:~]$ cat /usr/local/bin/mysql-test.sh #!/usr/bin/dash /usr/bin/su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=1 --max-test-fail=0 --mysqld=--binlog-format=mixed --force' mysql rm -rf /usr/share/mysql-test/var/*
rpl.rpl_binlog_index 'row' [ fail ] Test ended at 2017-01-20 16:56:16 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/'
rpl.sec_behind_master-5114 'stmt' [ fail ] Test ended at 2017-01-20 16:58:33 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' [ fail ] Test ended at 2017-01-20 16:59:24 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
it fails because there is no semisync plugin (you build without dynamic plugins, right?), but the test checks for that too late. A similar problem affects encryption tests that you mentioned in another email. Regards, Elena
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Am 20.01.2017 um 22:58 schrieb Elena Stepanova:
Hi Reindl,
On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with.
Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up
well, with --mysqld=--binlog-format=mixed at least it did somehow finish at all, i started it without at 7:00 PM as i left home, i came back home 10 minutes ago (4:00 AM) and it still did not finish but maybe that's just because the new encryption features where the test-suite just don't realize that they are not built and insetad sakip them all togehter it waits for every peice 3 seconds Failed to start mysqld.1 - skipping '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-cbc,xtradb/' ***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption 2017-01-20 19:01:51 140487478450496 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:51 140487478450496 [ERROR] Aborting worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7618, winpid: 7618, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7641, winpid: 7641, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7646, winpid: 7646, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7651, winpid: 7651, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7656, winpid: 7656, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7661, winpid: 7661, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7666, winpid: 7666, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7701, winpid: 7701, exit: 1792] died after mysql-test-run waited 2.9 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb_page_encryption_key_change 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 19:02:05 CURRENT_TEST: encryption.innodb_first_page CURRENT_TEST: encryption.innodb-log-encrypt CURRENT_TEST: encryption.innodb-page_encryption_log_encryption CURRENT_TEST: encryption.innodb-missing-key CURRENT_TEST: encryption.innodb_encryption_row_compressed CURRENT_TEST: encryption.innodb_encryption_filekeys CURRENT_TEST: encryption.innodb_encryption_is CURRENT_TEST: encryption.innochecksum CURRENT_TEST: encryption.innodb-bad-key-change CURRENT_TEST: encryption.innodb-discard-import CURRENT_TEST: encryption.innodb-discard-import-change CURRENT_TEST: encryption.innodb-encr-threads CURRENT_TEST: encryption.innodb-encryption-alter CURRENT_TEST: encryption.innodb-page_encryption CURRENT_TEST: encryption.innodb_page_encryption_key_change Failed to start mysqld.1 - skipping '/usr/share/mysql-test/var/log/encryption.innodb_page_encryption_key_change-cbc,xtradb/' worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7724, winpid: 7724, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ***Warnings generated in error logs during shutdown after running tests: encryption.innodb_page_encryption_key_change 2017-01-20 19:01:55 140380436027712 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:55 140380436027712 [ERROR] Aborting worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7747, winpid: 7747, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7770, winpid: 7770, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7793, winpid: 7793, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7817, winpid: 7817, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7840, winpid: 7840, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7863, winpid: 7863, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7886, winpid: 7886, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7909, winpid: 7909, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ^C Sitzung beendet, Shell wird abgewürgt ?wrong class (hack attempt?): $VAR1 = \undef; $VAR2 = ' 1234My::Test main.mysql_client_testname in_overlay mysql_client_test shortname &--plugin-load-add=$AUTH_TEST_PLUGIN_SO slave_opt ./usr/share/mysql-test/t/mysql_client_test.testpath &--plugin-load-add=$AUTH_TEST_PLUGIN_SO --general-log 3--general-log-file=$MYSQLTEST_VARDIR/log/master.log --log-output=FILE,TABLE --max-allowed-packet=32000000 master_opt template_pathMy::Suite::Main /usr/share/mysql-test/rrdiropts mainnameX derived_view show_explain_non_select events_stress func_hybrid_type myisam_mrr cast signal_code change_user innodb_mysql_lock sp-prelocking order_by_sortkey mdl_sync mysqld--defaults-file events_bugs tmp_table_count-7586 udf_debug_sync multi_statement parser_stack func_if unsafe_binlog_innodb bool ctype_cp1250_ch mysqltest ctype_ldml lock mysqld_option_err sp-code ?myisam_enable_keys-10506 information_schema_db ctype_gbk_binlog odbc variables tablelock join_outer_innodb dyncol debug_sync join_nested sighup-6580 func_test truncate_coverage group_min_max bug58669 mysql_locale_posix ipv4_as_ipv6 gis-rt-precise varbinary key fulltext3 kill_processlist-6619 myisam_crash_before_flush_keys trigger_null-8605 ps_4heap mysqlbinlog get_diagnostics select_safe \\0'; ^C ? abgewürgt. [root@testserver:~]$ ^C
Hi Reindl, On 01/21/2017 05:11 AM, Reindl Harald wrote:
Am 20.01.2017 um 22:58 schrieb Elena Stepanova:
Hi Reindl,
On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with.
Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up
well, with --mysqld=--binlog-format=mixed at least it did somehow finish at all, i started it without at 7:00 PM as i left home, i came back home 10 minutes ago (4:00 AM) and it still did not finish
but maybe that's just because the new encryption features where the test-suite just don't realize that they are not built and insetad sakip them all togehter it waits for every peice 3 seconds
Well, some failures can prolong the torture, but really it's probably a combination of factors. Still, 9 hours is very long even for a worst-case scenario, so it would be interesting to look at the full MTR output to understand what's happening. Without seeing it, importantly execution times of successful tests, I can only guess, but if binlog_format setting was the only thing that changed between the runs, and if you always run with '--max-test-fail=0 --force', most likely the culprit is the execution time of rpl suite, worsened by general low performance. rpl is the longest suite of all, and since it's running in full now, it can take a lot of time (which is why I agree that running tests with only one binlog_format is a reasonable demand). Before, when you ran tests with '--mysqld=--binlog-format=mixed', a big part of this suite and parts of some other suites either were skipped or failed. You are running tests on disk, rather than in memory. Latency for on-disk runs can be quite bad, depending on the machine. Replication tests in particular are quite sensitive to this. Here is an example from my laptop: on disk: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 41647 in memory: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 251 The fact that tests run without parallel also doesn't help. If you have enough memory, it's worth considering parallel execution -- every test will take longer, but the overall duration might decrease significantly. Regards, Elena
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-cbc,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption
2017-01-20 19:01:51 140487478450496 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:51 140487478450496 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7618, winpid: 7618, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7641, winpid: 7641, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7646, winpid: 7646, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7651, winpid: 7651, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7656, winpid: 7656, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7661, winpid: 7661, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7666, winpid: 7666, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7701, winpid: 7701, exit: 1792] died after mysql-test-run waited 2.9 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb_page_encryption_key_change 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 19:02:05
CURRENT_TEST: encryption.innodb_first_page CURRENT_TEST: encryption.innodb-log-encrypt CURRENT_TEST: encryption.innodb-page_encryption_log_encryption CURRENT_TEST: encryption.innodb-missing-key CURRENT_TEST: encryption.innodb_encryption_row_compressed CURRENT_TEST: encryption.innodb_encryption_filekeys CURRENT_TEST: encryption.innodb_encryption_is CURRENT_TEST: encryption.innochecksum CURRENT_TEST: encryption.innodb-bad-key-change CURRENT_TEST: encryption.innodb-discard-import CURRENT_TEST: encryption.innodb-discard-import-change CURRENT_TEST: encryption.innodb-encr-threads CURRENT_TEST: encryption.innodb-encryption-alter CURRENT_TEST: encryption.innodb-page_encryption CURRENT_TEST: encryption.innodb_page_encryption_key_change
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb_page_encryption_key_change-cbc,xtradb/'
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7724, winpid: 7724, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ***Warnings generated in error logs during shutdown after running tests: encryption.innodb_page_encryption_key_change
2017-01-20 19:01:55 140380436027712 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:55 140380436027712 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7747, winpid: 7747, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7770, winpid: 7770, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7793, winpid: 7793, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7817, winpid: 7817, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7840, winpid: 7840, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7863, winpid: 7863, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7886, winpid: 7886, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7909, winpid: 7909, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created.
^C Sitzung beendet, Shell wird abgewürgt ?wrong class (hack attempt?): $VAR1 = \undef; $VAR2 = ' 1234My::Test
main.mysql_client_testname in_overlay mysql_client_test shortname &--plugin-load-add=$AUTH_TEST_PLUGIN_SO slave_opt ./usr/share/mysql-test/t/mysql_client_test.testpath &--plugin-load-add=$AUTH_TEST_PLUGIN_SO --general-log 3--general-log-file=$MYSQLTEST_VARDIR/log/master.log --log-output=FILE,TABLE --max-allowed-packet=32000000 master_opt template_pathMy::Suite::Main /usr/share/mysql-test/rrdiropts mainnameX
derived_view show_explain_non_select events_stress func_hybrid_type
myisam_mrr cast
signal_code
change_user innodb_mysql_lock sp-prelocking order_by_sortkey mdl_sync mysqld--defaults-file
events_bugs tmp_table_count-7586 udf_debug_sync multi_statement
parser_stack func_if unsafe_binlog_innodb bool ctype_cp1250_ch mysqltest
ctype_ldml lock mysqld_option_err sp-code ?myisam_enable_keys-10506 information_schema_db ctype_gbk_binlog odbc variables tablelock join_outer_innodb dyncol
debug_sync
join_nested
sighup-6580 func_test truncate_coverage group_min_max bug58669 mysql_locale_posix
ipv4_as_ipv6 gis-rt-precise varbinary key fulltext3 kill_processlist-6619 myisam_crash_before_flush_keys trigger_null-8605 ps_4heap
mysqlbinlog get_diagnostics
select_safe \\0'; ^C ? abgewürgt.
[root@testserver:~]$ ^C
i stepped back to --mysqld=--binlog-format=mixed and started to use --suites= su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=4 --max-test-fail=0 --force --suites="main-,binlog-,csv-,funcs_1-,funcs_2-,handler-,heap-,maria-,optimizer_unfixed_bugs-,parts-,percona-,roles-,rpl-,sys_vars-,unit-,vcol-" --mysqld=--binlog-format=mixed' mysql Completed: Failed 15/1797 tests, 99.17% were successful. Failing test(s): rpl.rpl_not_null_innodb rpl.rpl_binlog_index rpl.rpl_semi_sync_event_after_sync rpl.sec_behind_master-5114 rpl.rpl_ip_mix rpl.rpl_ip_mix2 rpl.rpl_ipv6 sys_vars.sysvars_server_notembedded main.ipv4_and_ipv6 main.ipv6 main.mysql_client_test_nonblock main.multi_update main.set_statement_notembedded_binlog main.view maria.encrypt-wrong-key with parallel and tmpfs the whole test takes only some minutes (it was also not that slow with mixed, only one test and on-disk since the machine has horsepwoer) however most of the failing tests should not have been started at all because binlog mode or features just not compiled by intention and i have included the details below the cmkae flags _______________________________________ cmake . -DBUILD_CONFIG=mysql_release \ -DFEATURE_SET="large" \ -DCMAKE_INSTALL_PREFIX="%{_prefix}" \ -DINSTALL_INCLUDEDIR=include/mysql \ -DINSTALL_LAYOUT=RPM \ -DINSTALL_LIBDIR="%{_lib}/mysql" \ -DINSTALL_MANDIR=share/man \ -DINSTALL_MYSQLSHAREDIR=share/mysql \ -DINSTALL_MYSQLTESTDIR=share/mysql-test \ -DINSTALL_PLUGINDIR="%{_lib}/mysql/plugin" \ -DINSTALL_SBINDIR=libexec \ -DINSTALL_SCRIPTDIR=bin \ -DINSTALL_SQLBENCHDIR= \ -DINSTALL_SUPPORTFILESDIR=share/mysql \ -DMYSQL_DATADIR="%{_sharedstatedir}/mysql" \ -DMYSQL_UNIX_ADDR="%{_sharedstatedir}/mysql/mysql.sock" \ -DENABLED_PROFILING=OFF \ -DENABLE_DEBUG_SYNC=OFF \ -DENABLE_DTRACE=OFF \ -DPLUGIN_ARCHIVE=NO \ -DPLUGIN_BLACKHOLE=NO \ -DPLUGIN_CASSANDRA=NO \ -DPLUGIN_FEDERATED=NO \ -DPLUGIN_FEEDBACK=NO \ -DPLUGIN_MROONGA=NO \ -DPLUGIN_OQGRAPH=NO \ -DPLUGIN_PARTITION=NO \ -DPLUGIN_PERFSCHEMA=NO \ -DPLUGIN_SEQUENCE=NO \ -DPLUGIN_SPHINX=NO \ -DPLUGIN_SPIDER=NO \ -DPLUGIN_XTRADB=YES \ -DWITHOUT_DYNAMIC_PLUGINS=ON \ -DWITHOUT_TOKUDB=ON \ -DWITH_ATOMIC_OPS=smp \ -DWITH_EMBEDDED_SERVER=OFF \ -DWITH_INNODB_DISALLOW_WRITES=OFF \ -DWITH_JEMALLOC=system \ -DWITH_LIBWRAP=OFF \ -DWITH_PIC=ON \ -DWITH_READLINE=OFF \ -DWITH_SAFEMALLOC=OFF \ -DWITH_SSL=system \ -DWITH_VALGRIND=OFF \ -DWITH_WSREP=OFF \ -DWITH_ZLIB=system _______________________________________ rpl.rpl_not_null_innodb 'row,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:09:28 CURRENT_TEST: rpl.rpl_not_null_innodb mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_not_null_innodb.test at line 15: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/2/log/rpl.rpl_not_null_innodb-row,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_not_null_innodb-row,xtradb/' _______________________________________ rpl.rpl_binlog_index 'row' w1 [ fail ] Test ended at 2017-01-21 15:09:40 CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/1/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' _______________________________________ rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:10:14 CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point' The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC; - saving '/usr/share/mysql-test/var/2/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' _______________________________________ rpl.sec_behind_master-5114 'stmt' w4 [ fail ] Test ended at 2017-01-21 15:10:24 CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first The result from queries just before the failure was: include/master-slave.inc - saving '/usr/share/mysql-test/var/4/log/rpl.sec_behind_master-5114-stmt/' to '/usr/share/mysql-test/var/log/rpl.sec_behind_master-5114-stmt/' _______________________________________ rpl.rpl_ip_mix w2 [ fail ] Test ended at 2017-01-21 15:11:52 CURRENT_TEST: rpl.rpl_ip_mix mysqltest: In included file "./include/rpl_ip_mix.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix.test at line 11: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address") The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT); - saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix/' rpl.rpl_ip_mix2 w2 [ fail ] Test ended at 2017-01-21 15:11:52 CURRENT_TEST: rpl.rpl_ip_mix2 mysqltest: In included file "./include/rpl_ip_mix2.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix2.test at line 11: At line 4: query 'connect slave,$IPv6,root,,test,$SLAVE_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address") The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,127.0.0.1,root,,test,MASTER_MYPORT); connect (slave,::1,root,,test,SLAVE_MYPORT); - saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix2/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix2/' rpl.rpl_ipv4_as_ipv6 w2 [ pass ] 55 rpl.rpl_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:11:56 CURRENT_TEST: rpl.rpl_ipv6 mysqltest: In included file "./include/rpl_ipv6.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ipv6.test at line 13: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address") The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT); - saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ipv6/' to '/usr/share/mysql-test/var/log/rpl.rpl_ipv6/' _______________________________________ sys_vars.sysvars_server_notembedded '64bit' w2 [ fail ] Test ended at 2017-01-21 15:12:32 CURRENT_TEST: sys_vars.sysvars_server_notembedded --- /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result 2017-01-17 20:38:24.000000000 +0100 +++ /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.reject 2017-01-21 15:12:32.120425458 +0100 mysqltest: Result length mismatch - saving '/usr/share/mysql-test/var/2/log/sys_vars.sysvars_server_notembedded-64bit/' to '/usr/share/mysql-test/var/log/sys_vars.sysvars_server_notembedded-64bit/' _______________________________________ main.ipv4_and_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:38 CURRENT_TEST: main.ipv4_and_ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv4_and_ipv6.test at line 7: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 Output from before failure: _______________________________________ main.ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:39 CURRENT_TEST: main.ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv6.test at line 14: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 _______________________________________ main.mysql_client_test_nonblock w3 [ fail ] Test ended at 2017-01-21 15:13:46 CURRENT_TEST: main.mysql_client_test_nonblock mysqltest: At line 18: exec of '/usr/bin/mysql_client_test --defaults-file=/usr/share/mysql-test/var/3/my.cnf --testcase --vardir=/usr/share/mysql-test/var/3 --non-blocking-api --getopt-ll-test=25600M >> /usr/share/mysql-test/var/3/log/mysql_client_test.out.log 2>&1' failed, error: 256, status: 1, errno: 2 Output from before failure: call mtr.add_suppression(" Error reading file './client_test_db/test_frm_bug.frm'"); _______________________________________ main.multi_update 'xtradb' w2 [ fail ] Test ended at 2017-01-21 15:14:10 CURRENT_TEST: main.multi_update --- /usr/share/mysql-test/r/multi_update.result 2017-01-17 20:38:20.000000000 +0100 +++ /usr/share/mysql-test/r/multi_update.reject 2017-01-21 15:14:09.912153479 +0100 @@ -1055,7 +1055,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. UPDATE (SELECT 128 as col1) x, table_11757486 SET field1=x.col1; ERROR 22003: Out of range value for column 'field1' at row 1 UPDATE table_11757486 SET field1=128; @@ -1069,7 +1068,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. DROP TABLE table_11757486; SET SESSION SQL_MODE=default; end of 10.0 tests mysqltest: Result length mismatch _______________________________________ main.set_statement_notembedded_binlog w2 [ fail ] Test ended at 2017-01-21 15:14:33 CURRENT_TEST: main.set_statement_notembedded_binlog --- /usr/share/mysql-test/r/set_statement_notembedded_binlog.result 2017-01-17 20:38:21.000000000 +0100 +++ /usr/share/mysql-test/r/set_statement_notembedded_binlog.reject 2017-01-21 15:14:33.553868145 +0100 @@ -34,23 +34,10 @@ f1() 1113 111313 -Warnings: -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. show binlog events limit 16, 100; _______________________________________ main.view w3 [ fail ] Test ended at 2017-01-21 15:15:15 CURRENT_TEST: main.view mysqltest: At line 5501: query 'alter table v1 check partition p1' failed: 1289: The 'partitioning' feature is disabled; you need MariaDB built with '--with-plugin-partition' to have it working _______________________________________ maria.encrypt-wrong-key w3 [ fail ] Test ended at 2017-01-21 15:15:24 CURRENT_TEST: maria.encrypt-wrong-key Server [mysqld.1 - pid: 30821, winpid: 30821, exit: 512] failed during test run Server log from this test: ----------SERVER LOG START----------- 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Normal shutdown 2017-01-21 15:15:23 139933618535168 [Note] Event Scheduler: Purging the queue. 0 events 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Shutdown complete 2017-01-21 15:15:24 139668697172288 [Note] /usr/libexec/mysqld (mysqld 10.1.21-MariaDB) starting as process 30823 ... 2017-01-21 15:15:24 139668697172288 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162) 2017-01-21 15:15:24 139668697172288 [ERROR] Can't open shared library '/usr/lib64/mysql/plugin/file_key_management.so' (errno: 2, cannot open shared object file: No such file or directory) _______________________________________ Am 21.01.2017 um 14:28 schrieb Elena Stepanova:
Hi Reindl,
On 01/21/2017 05:11 AM, Reindl Harald wrote:
Am 20.01.2017 um 22:58 schrieb Elena Stepanova:
Hi Reindl,
On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with.
Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up
well, with --mysqld=--binlog-format=mixed at least it did somehow finish at all, i started it without at 7:00 PM as i left home, i came back home 10 minutes ago (4:00 AM) and it still did not finish
but maybe that's just because the new encryption features where the test-suite just don't realize that they are not built and insetad sakip them all togehter it waits for every peice 3 seconds
Well, some failures can prolong the torture, but really it's probably a combination of factors. Still, 9 hours is very long even for a worst-case scenario, so it would be interesting to look at the full MTR output to understand what's happening.
Without seeing it, importantly execution times of successful tests, I can only guess, but if binlog_format setting was the only thing that changed between the runs, and if you always run with '--max-test-fail=0 --force', most likely the culprit is the execution time of rpl suite, worsened by general low performance.
rpl is the longest suite of all, and since it's running in full now, it can take a lot of time (which is why I agree that running tests with only one binlog_format is a reasonable demand). Before, when you ran tests with '--mysqld=--binlog-format=mixed', a big part of this suite and parts of some other suites either were skipped or failed.
You are running tests on disk, rather than in memory. Latency for on-disk runs can be quite bad, depending on the machine. Replication tests in particular are quite sensitive to this. Here is an example from my laptop:
on disk: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 41647 in memory: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 251
The fact that tests run without parallel also doesn't help. If you have enough memory, it's worth considering parallel execution -- every test will take longer, but the overall duration might decrease significantly.
Regards, Elena
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-cbc,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption
2017-01-20 19:01:51 140487478450496 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:51 140487478450496 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7618, winpid: 7618, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7641, winpid: 7641, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7646, winpid: 7646, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7651, winpid: 7651, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7656, winpid: 7656, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7661, winpid: 7661, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7666, winpid: 7666, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7701, winpid: 7701, exit: 1792] died after mysql-test-run waited 2.9 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb_page_encryption_key_change 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 19:02:05
CURRENT_TEST: encryption.innodb_first_page CURRENT_TEST: encryption.innodb-log-encrypt CURRENT_TEST: encryption.innodb-page_encryption_log_encryption CURRENT_TEST: encryption.innodb-missing-key CURRENT_TEST: encryption.innodb_encryption_row_compressed CURRENT_TEST: encryption.innodb_encryption_filekeys CURRENT_TEST: encryption.innodb_encryption_is CURRENT_TEST: encryption.innochecksum CURRENT_TEST: encryption.innodb-bad-key-change CURRENT_TEST: encryption.innodb-discard-import CURRENT_TEST: encryption.innodb-discard-import-change CURRENT_TEST: encryption.innodb-encr-threads CURRENT_TEST: encryption.innodb-encryption-alter CURRENT_TEST: encryption.innodb-page_encryption CURRENT_TEST: encryption.innodb_page_encryption_key_change
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb_page_encryption_key_change-cbc,xtradb/'
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7724, winpid: 7724, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ***Warnings generated in error logs during shutdown after running tests: encryption.innodb_page_encryption_key_change
2017-01-20 19:01:55 140380436027712 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:55 140380436027712 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7747, winpid: 7747, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7770, winpid: 7770, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7793, winpid: 7793, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7817, winpid: 7817, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7840, winpid: 7840, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7863, winpid: 7863, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7886, winpid: 7886, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7909, winpid: 7909, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created.
^C Sitzung beendet, Shell wird abgewürgt ?wrong class (hack attempt?): $VAR1 = \undef; $VAR2 = ' 1234My::Test
main.mysql_client_testname in_overlay mysql_client_test shortname &--plugin-load-add=$AUTH_TEST_PLUGIN_SO slave_opt ./usr/share/mysql-test/t/mysql_client_test.testpath &--plugin-load-add=$AUTH_TEST_PLUGIN_SO --general-log 3--general-log-file=$MYSQLTEST_VARDIR/log/master.log --log-output=FILE,TABLE --max-allowed-packet=32000000 master_opt template_pathMy::Suite::Main /usr/share/mysql-test/rrdiropts mainnameX
derived_view show_explain_non_select events_stress func_hybrid_type
myisam_mrr cast
signal_code
change_user innodb_mysql_lock sp-prelocking order_by_sortkey mdl_sync mysqld--defaults-file
events_bugs tmp_table_count-7586 udf_debug_sync multi_statement
parser_stack func_if unsafe_binlog_innodb bool ctype_cp1250_ch mysqltest
ctype_ldml lock mysqld_option_err sp-code ?myisam_enable_keys-10506 information_schema_db ctype_gbk_binlog odbc variables tablelock join_outer_innodb dyncol
debug_sync
join_nested
sighup-6580 func_test truncate_coverage group_min_max bug58669 mysql_locale_posix
ipv4_as_ipv6 gis-rt-precise varbinary key fulltext3 kill_processlist-6619 myisam_crash_before_flush_keys trigger_null-8605 ps_4heap
mysqlbinlog get_diagnostics
select_safe \\0'; ^C ? abgewürgt.
[root@testserver:~]$ ^C
-- Reindl Harald the lounge interactive design GmbH A-1060 Vienna, Hofmühlgasse 17 CTO / CISO / Software-Development m: +43 676 40 221 40 p: +43 1 595 3999 33 http://www.thelounge.net/
Hi Reindl, Dirty exit and further "operation cannot be performed" in replication tests (3 occurrences below) is now filed as https://jira.mariadb.org/browse/MDEV-11861 The failure if semisync plugin is missing (1 occurrence) is filed as https://jira.mariadb.org/browse/MDEV-11862 The failure when encryption plugin is missing (1 occurrence) is filed as https://jira.mariadb.org/browse/MDEV-11865 main.view doesn't check whether the partition plugin exists. It's filed as https://jira.mariadb.org/browse/MDEV-11864 main.mysql_client_test_nonblock -- I have no idea yet what it is, so can't make any promises, but it's reproducible with your build options, so I've filed it as https://jira.mariadb.org/browse/MDEV-11863 for further investigation. The failure with ipv6 (5 occurrences) hasn't been filed yet. It would be nice to have it fixed, but not sure yet what it would cost, we need to look into it. Mismatch in main.analyze_format_json (in another email) is a bug, filed as https://jira.mariadb.org/browse/MDEV-11866 Some other "mismatch" failures (in this and separate emails) are the example why MTR cannot be guaranteed to succeed with arbitrary build/startup options -- it depends on the exact output too much. It's not realistic to make all tests completely universal, they would be too generic to stay useful. Regards, Elena On 01/21/2017 04:27 PM, Reindl Harald wrote:
i stepped back to --mysqld=--binlog-format=mixed and started to use --suites=
su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=4 --max-test-fail=0 --force --suites="main-,binlog-,csv-,funcs_1-,funcs_2-,handler-,heap-,maria-,optimizer_unfixed_bugs-,parts-,percona-,roles-,rpl-,sys_vars-,unit-,vcol-" --mysqld=--binlog-format=mixed' mysql
Completed: Failed 15/1797 tests, 99.17% were successful. Failing test(s): rpl.rpl_not_null_innodb rpl.rpl_binlog_index rpl.rpl_semi_sync_event_after_sync rpl.sec_behind_master-5114 rpl.rpl_ip_mix rpl.rpl_ip_mix2 rpl.rpl_ipv6 sys_vars.sysvars_server_notembedded main.ipv4_and_ipv6 main.ipv6 main.mysql_client_test_nonblock main.multi_update main.set_statement_notembedded_binlog main.view maria.encrypt-wrong-key
with parallel and tmpfs the whole test takes only some minutes (it was also not that slow with mixed, only one test and on-disk since the machine has horsepwoer) however
most of the failing tests should not have been started at all because binlog mode or features just not compiled by intention and i have included the details below the cmkae flags _______________________________________
cmake . -DBUILD_CONFIG=mysql_release \ -DFEATURE_SET="large" \ -DCMAKE_INSTALL_PREFIX="%{_prefix}" \ -DINSTALL_INCLUDEDIR=include/mysql \ -DINSTALL_LAYOUT=RPM \ -DINSTALL_LIBDIR="%{_lib}/mysql" \ -DINSTALL_MANDIR=share/man \ -DINSTALL_MYSQLSHAREDIR=share/mysql \ -DINSTALL_MYSQLTESTDIR=share/mysql-test \ -DINSTALL_PLUGINDIR="%{_lib}/mysql/plugin" \ -DINSTALL_SBINDIR=libexec \ -DINSTALL_SCRIPTDIR=bin \ -DINSTALL_SQLBENCHDIR= \ -DINSTALL_SUPPORTFILESDIR=share/mysql \ -DMYSQL_DATADIR="%{_sharedstatedir}/mysql" \ -DMYSQL_UNIX_ADDR="%{_sharedstatedir}/mysql/mysql.sock" \ -DENABLED_PROFILING=OFF \ -DENABLE_DEBUG_SYNC=OFF \ -DENABLE_DTRACE=OFF \ -DPLUGIN_ARCHIVE=NO \ -DPLUGIN_BLACKHOLE=NO \ -DPLUGIN_CASSANDRA=NO \ -DPLUGIN_FEDERATED=NO \ -DPLUGIN_FEEDBACK=NO \ -DPLUGIN_MROONGA=NO \ -DPLUGIN_OQGRAPH=NO \ -DPLUGIN_PARTITION=NO \ -DPLUGIN_PERFSCHEMA=NO \ -DPLUGIN_SEQUENCE=NO \ -DPLUGIN_SPHINX=NO \ -DPLUGIN_SPIDER=NO \ -DPLUGIN_XTRADB=YES \ -DWITHOUT_DYNAMIC_PLUGINS=ON \ -DWITHOUT_TOKUDB=ON \ -DWITH_ATOMIC_OPS=smp \ -DWITH_EMBEDDED_SERVER=OFF \ -DWITH_INNODB_DISALLOW_WRITES=OFF \ -DWITH_JEMALLOC=system \ -DWITH_LIBWRAP=OFF \ -DWITH_PIC=ON \ -DWITH_READLINE=OFF \ -DWITH_SAFEMALLOC=OFF \ -DWITH_SSL=system \ -DWITH_VALGRIND=OFF \ -DWITH_WSREP=OFF \ -DWITH_ZLIB=system _______________________________________
rpl.rpl_not_null_innodb 'row,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:09:28
CURRENT_TEST: rpl.rpl_not_null_innodb mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_not_null_innodb.test at line 15: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_not_null_innodb-row,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_not_null_innodb-row,xtradb/' _______________________________________
rpl.rpl_binlog_index 'row' w1 [ fail ] Test ended at 2017-01-21 15:09:40
CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/1/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' _______________________________________
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:10:14
CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point'
The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC;
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
_______________________________________
rpl.sec_behind_master-5114 'stmt' w4 [ fail ] Test ended at 2017-01-21 15:10:24
CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/4/log/rpl.sec_behind_master-5114-stmt/' to '/usr/share/mysql-test/var/log/rpl.sec_behind_master-5114-stmt/' _______________________________________
rpl.rpl_ip_mix w2 [ fail ] Test ended at 2017-01-21 15:11:52
CURRENT_TEST: rpl.rpl_ip_mix mysqltest: In included file "./include/rpl_ip_mix.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix.test at line 11: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix/' rpl.rpl_ip_mix2 w2 [ fail ] Test ended at 2017-01-21 15:11:52
CURRENT_TEST: rpl.rpl_ip_mix2 mysqltest: In included file "./include/rpl_ip_mix2.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix2.test at line 11: At line 4: query 'connect slave,$IPv6,root,,test,$SLAVE_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,127.0.0.1,root,,test,MASTER_MYPORT); connect (slave,::1,root,,test,SLAVE_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix2/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix2/' rpl.rpl_ipv4_as_ipv6 w2 [ pass ] 55 rpl.rpl_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:11:56
CURRENT_TEST: rpl.rpl_ipv6 mysqltest: In included file "./include/rpl_ipv6.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ipv6.test at line 13: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ipv6/' to '/usr/share/mysql-test/var/log/rpl.rpl_ipv6/' _______________________________________
sys_vars.sysvars_server_notembedded '64bit' w2 [ fail ] Test ended at 2017-01-21 15:12:32
CURRENT_TEST: sys_vars.sysvars_server_notembedded --- /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result 2017-01-17 20:38:24.000000000 +0100 +++ /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.reject 2017-01-21 15:12:32.120425458 +0100 mysqltest: Result length mismatch - saving '/usr/share/mysql-test/var/2/log/sys_vars.sysvars_server_notembedded-64bit/' to '/usr/share/mysql-test/var/log/sys_vars.sysvars_server_notembedded-64bit/'
_______________________________________
main.ipv4_and_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:38
CURRENT_TEST: main.ipv4_and_ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv4_and_ipv6.test at line 7: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 Output from before failure: _______________________________________
main.ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:39
CURRENT_TEST: main.ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv6.test at line 14: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 _______________________________________
main.mysql_client_test_nonblock w3 [ fail ] Test ended at 2017-01-21 15:13:46
CURRENT_TEST: main.mysql_client_test_nonblock mysqltest: At line 18: exec of '/usr/bin/mysql_client_test --defaults-file=/usr/share/mysql-test/var/3/my.cnf --testcase --vardir=/usr/share/mysql-test/var/3 --non-blocking-api --getopt-ll-test=25600M >> /usr/share/mysql-test/var/3/log/mysql_client_test.out.log 2>&1' failed, error: 256, status: 1, errno: 2 Output from before failure: call mtr.add_suppression(" Error reading file './client_test_db/test_frm_bug.frm'"); _______________________________________
main.multi_update 'xtradb' w2 [ fail ] Test ended at 2017-01-21 15:14:10
CURRENT_TEST: main.multi_update --- /usr/share/mysql-test/r/multi_update.result 2017-01-17 20:38:20.000000000 +0100 +++ /usr/share/mysql-test/r/multi_update.reject 2017-01-21 15:14:09.912153479 +0100 @@ -1055,7 +1055,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. UPDATE (SELECT 128 as col1) x, table_11757486 SET field1=x.col1; ERROR 22003: Out of range value for column 'field1' at row 1 UPDATE table_11757486 SET field1=128; @@ -1069,7 +1068,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. DROP TABLE table_11757486; SET SESSION SQL_MODE=default; end of 10.0 tests
mysqltest: Result length mismatch _______________________________________
main.set_statement_notembedded_binlog w2 [ fail ] Test ended at 2017-01-21 15:14:33
CURRENT_TEST: main.set_statement_notembedded_binlog --- /usr/share/mysql-test/r/set_statement_notembedded_binlog.result 2017-01-17 20:38:21.000000000 +0100 +++ /usr/share/mysql-test/r/set_statement_notembedded_binlog.reject 2017-01-21 15:14:33.553868145 +0100 @@ -34,23 +34,10 @@ f1() 1113 111313 -Warnings: -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. show binlog events limit 16, 100; _______________________________________
main.view w3 [ fail ] Test ended at 2017-01-21 15:15:15
CURRENT_TEST: main.view mysqltest: At line 5501: query 'alter table v1 check partition p1' failed: 1289: The 'partitioning' feature is disabled; you need MariaDB built with '--with-plugin-partition' to have it working _______________________________________
maria.encrypt-wrong-key w3 [ fail ] Test ended at 2017-01-21 15:15:24
CURRENT_TEST: maria.encrypt-wrong-key
Server [mysqld.1 - pid: 30821, winpid: 30821, exit: 512] failed during test run Server log from this test: ----------SERVER LOG START----------- 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Normal shutdown
2017-01-21 15:15:23 139933618535168 [Note] Event Scheduler: Purging the queue. 0 events 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Shutdown complete
2017-01-21 15:15:24 139668697172288 [Note] /usr/libexec/mysqld (mysqld 10.1.21-MariaDB) starting as process 30823 ... 2017-01-21 15:15:24 139668697172288 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162) 2017-01-21 15:15:24 139668697172288 [ERROR] Can't open shared library '/usr/lib64/mysql/plugin/file_key_management.so' (errno: 2, cannot open shared object file: No such file or directory) _______________________________________
Am 21.01.2017 um 14:28 schrieb Elena Stepanova:
Hi Reindl,
On 01/21/2017 05:11 AM, Reindl Harald wrote:
Am 20.01.2017 um 22:58 schrieb Elena Stepanova:
Hi Reindl,
On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with.
Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up
well, with --mysqld=--binlog-format=mixed at least it did somehow finish at all, i started it without at 7:00 PM as i left home, i came back home 10 minutes ago (4:00 AM) and it still did not finish
but maybe that's just because the new encryption features where the test-suite just don't realize that they are not built and insetad sakip them all togehter it waits for every peice 3 seconds
Well, some failures can prolong the torture, but really it's probably a combination of factors. Still, 9 hours is very long even for a worst-case scenario, so it would be interesting to look at the full MTR output to understand what's happening.
Without seeing it, importantly execution times of successful tests, I can only guess, but if binlog_format setting was the only thing that changed between the runs, and if you always run with '--max-test-fail=0 --force', most likely the culprit is the execution time of rpl suite, worsened by general low performance.
rpl is the longest suite of all, and since it's running in full now, it can take a lot of time (which is why I agree that running tests with only one binlog_format is a reasonable demand). Before, when you ran tests with '--mysqld=--binlog-format=mixed', a big part of this suite and parts of some other suites either were skipped or failed.
You are running tests on disk, rather than in memory. Latency for on-disk runs can be quite bad, depending on the machine. Replication tests in particular are quite sensitive to this. Here is an example from my laptop:
on disk: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 41647 in memory: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 251
The fact that tests run without parallel also doesn't help. If you have enough memory, it's worth considering parallel execution -- every test will take longer, but the overall duration might decrease significantly.
Regards, Elena
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-cbc,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption
2017-01-20 19:01:51 140487478450496 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:51 140487478450496 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7618, winpid: 7618, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7641, winpid: 7641, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7646, winpid: 7646, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7651, winpid: 7651, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7656, winpid: 7656, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7661, winpid: 7661, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7666, winpid: 7666, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7701, winpid: 7701, exit: 1792] died after mysql-test-run waited 2.9 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb_page_encryption_key_change 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 19:02:05
CURRENT_TEST: encryption.innodb_first_page CURRENT_TEST: encryption.innodb-log-encrypt CURRENT_TEST: encryption.innodb-page_encryption_log_encryption CURRENT_TEST: encryption.innodb-missing-key CURRENT_TEST: encryption.innodb_encryption_row_compressed CURRENT_TEST: encryption.innodb_encryption_filekeys CURRENT_TEST: encryption.innodb_encryption_is CURRENT_TEST: encryption.innochecksum CURRENT_TEST: encryption.innodb-bad-key-change CURRENT_TEST: encryption.innodb-discard-import CURRENT_TEST: encryption.innodb-discard-import-change CURRENT_TEST: encryption.innodb-encr-threads CURRENT_TEST: encryption.innodb-encryption-alter CURRENT_TEST: encryption.innodb-page_encryption CURRENT_TEST: encryption.innodb_page_encryption_key_change
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb_page_encryption_key_change-cbc,xtradb/'
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7724, winpid: 7724, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ***Warnings generated in error logs during shutdown after running tests: encryption.innodb_page_encryption_key_change
2017-01-20 19:01:55 140380436027712 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:55 140380436027712 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7747, winpid: 7747, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7770, winpid: 7770, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7793, winpid: 7793, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7817, winpid: 7817, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7840, winpid: 7840, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7863, winpid: 7863, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7886, winpid: 7886, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7909, winpid: 7909, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created.
^C Sitzung beendet, Shell wird abgewürgt ?wrong class (hack attempt?): $VAR1 = \undef; $VAR2 = ' 1234My::Test
main.mysql_client_testname in_overlay mysql_client_test shortname &--plugin-load-add=$AUTH_TEST_PLUGIN_SO slave_opt ./usr/share/mysql-test/t/mysql_client_test.testpath &--plugin-load-add=$AUTH_TEST_PLUGIN_SO --general-log 3--general-log-file=$MYSQLTEST_VARDIR/log/master.log --log-output=FILE,TABLE --max-allowed-packet=32000000 master_opt template_pathMy::Suite::Main /usr/share/mysql-test/rrdiropts mainnameX
derived_view show_explain_non_select events_stress func_hybrid_type
myisam_mrr cast
signal_code
change_user innodb_mysql_lock sp-prelocking order_by_sortkey mdl_sync mysqld--defaults-file
events_bugs tmp_table_count-7586 udf_debug_sync multi_statement
parser_stack func_if unsafe_binlog_innodb bool ctype_cp1250_ch mysqltest
ctype_ldml lock mysqld_option_err sp-code ?myisam_enable_keys-10506 information_schema_db ctype_gbk_binlog odbc variables tablelock join_outer_innodb dyncol
debug_sync
join_nested
sighup-6580 func_test truncate_coverage group_min_max bug58669 mysql_locale_posix
ipv4_as_ipv6 gis-rt-precise varbinary key fulltext3 kill_processlist-6619 myisam_crash_before_flush_keys trigger_null-8605 ps_4heap
mysqlbinlog get_diagnostics
select_safe \\0'; ^C ? abgewürgt.
[root@testserver:~]$ ^C
thank you!
The failure with ipv6 (5 occurrences) hasn't been filed yet
https://bugs.mysql.com/bug.php?id=60511 Am 21.01.2017 um 17:04 schrieb Elena Stepanova:
Hi Reindl,
Dirty exit and further "operation cannot be performed" in replication tests (3 occurrences below) is now filed as https://jira.mariadb.org/browse/MDEV-11861
The failure if semisync plugin is missing (1 occurrence) is filed as https://jira.mariadb.org/browse/MDEV-11862
The failure when encryption plugin is missing (1 occurrence) is filed as https://jira.mariadb.org/browse/MDEV-11865
main.view doesn't check whether the partition plugin exists. It's filed as https://jira.mariadb.org/browse/MDEV-11864
main.mysql_client_test_nonblock -- I have no idea yet what it is, so can't make any promises, but it's reproducible with your build options, so I've filed it as https://jira.mariadb.org/browse/MDEV-11863 for further investigation.
The failure with ipv6 (5 occurrences) hasn't been filed yet. It would be nice to have it fixed, but not sure yet what it would cost, we need to look into it.
Mismatch in main.analyze_format_json (in another email) is a bug, filed as https://jira.mariadb.org/browse/MDEV-11866
Some other "mismatch" failures (in this and separate emails) are the example why MTR cannot be guaranteed to succeed with arbitrary build/startup options -- it depends on the exact output too much. It's not realistic to make all tests completely universal, they would be too generic to stay useful.
Regards, Elena
On 01/21/2017 04:27 PM, Reindl Harald wrote:
i stepped back to --mysqld=--binlog-format=mixed and started to use --suites=
su -c 'cd /usr/share/mysql-test; ./mysql-test-run.pl --parallel=4 --max-test-fail=0 --force --suites="main-,binlog-,csv-,funcs_1-,funcs_2-,handler-,heap-,maria-,optimizer_unfixed_bugs-,parts-,percona-,roles-,rpl-,sys_vars-,unit-,vcol-"
--mysqld=--binlog-format=mixed' mysql
Completed: Failed 15/1797 tests, 99.17% were successful. Failing test(s): rpl.rpl_not_null_innodb rpl.rpl_binlog_index rpl.rpl_semi_sync_event_after_sync rpl.sec_behind_master-5114 rpl.rpl_ip_mix rpl.rpl_ip_mix2 rpl.rpl_ipv6 sys_vars.sysvars_server_notembedded main.ipv4_and_ipv6 main.ipv6 main.mysql_client_test_nonblock main.multi_update main.set_statement_notembedded_binlog main.view maria.encrypt-wrong-key
with parallel and tmpfs the whole test takes only some minutes (it was also not that slow with mixed, only one test and on-disk since the machine has horsepwoer) however
most of the failing tests should not have been started at all because binlog mode or features just not compiled by intention and i have included the details below the cmkae flags _______________________________________
cmake . -DBUILD_CONFIG=mysql_release \ -DFEATURE_SET="large" \ -DCMAKE_INSTALL_PREFIX="%{_prefix}" \ -DINSTALL_INCLUDEDIR=include/mysql \ -DINSTALL_LAYOUT=RPM \ -DINSTALL_LIBDIR="%{_lib}/mysql" \ -DINSTALL_MANDIR=share/man \ -DINSTALL_MYSQLSHAREDIR=share/mysql \ -DINSTALL_MYSQLTESTDIR=share/mysql-test \ -DINSTALL_PLUGINDIR="%{_lib}/mysql/plugin" \ -DINSTALL_SBINDIR=libexec \ -DINSTALL_SCRIPTDIR=bin \ -DINSTALL_SQLBENCHDIR= \ -DINSTALL_SUPPORTFILESDIR=share/mysql \ -DMYSQL_DATADIR="%{_sharedstatedir}/mysql" \ -DMYSQL_UNIX_ADDR="%{_sharedstatedir}/mysql/mysql.sock" \ -DENABLED_PROFILING=OFF \ -DENABLE_DEBUG_SYNC=OFF \ -DENABLE_DTRACE=OFF \ -DPLUGIN_ARCHIVE=NO \ -DPLUGIN_BLACKHOLE=NO \ -DPLUGIN_CASSANDRA=NO \ -DPLUGIN_FEDERATED=NO \ -DPLUGIN_FEEDBACK=NO \ -DPLUGIN_MROONGA=NO \ -DPLUGIN_OQGRAPH=NO \ -DPLUGIN_PARTITION=NO \ -DPLUGIN_PERFSCHEMA=NO \ -DPLUGIN_SEQUENCE=NO \ -DPLUGIN_SPHINX=NO \ -DPLUGIN_SPIDER=NO \ -DPLUGIN_XTRADB=YES \ -DWITHOUT_DYNAMIC_PLUGINS=ON \ -DWITHOUT_TOKUDB=ON \ -DWITH_ATOMIC_OPS=smp \ -DWITH_EMBEDDED_SERVER=OFF \ -DWITH_INNODB_DISALLOW_WRITES=OFF \ -DWITH_JEMALLOC=system \ -DWITH_LIBWRAP=OFF \ -DWITH_PIC=ON \ -DWITH_READLINE=OFF \ -DWITH_SAFEMALLOC=OFF \ -DWITH_SSL=system \ -DWITH_VALGRIND=OFF \ -DWITH_WSREP=OFF \ -DWITH_ZLIB=system _______________________________________
rpl.rpl_not_null_innodb 'row,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:09:28
CURRENT_TEST: rpl.rpl_not_null_innodb mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_not_null_innodb.test at line 15: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_not_null_innodb-row,xtradb/' to '/usr/share/mysql-test/var/log/rpl.rpl_not_null_innodb-row,xtradb/' _______________________________________
rpl.rpl_binlog_index 'row' w1 [ fail ] Test ended at 2017-01-21 15:09:40
CURRENT_TEST: rpl.rpl_binlog_index mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/rpl_binlog_index.test at line 20: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/1/log/rpl.rpl_binlog_index-row/' to '/usr/share/mysql-test/var/log/rpl.rpl_binlog_index-row/' _______________________________________
rpl.rpl_semi_sync_event_after_sync 'mix,xtradb' w2 [ fail ] Test ended at 2017-01-21 15:10:14
CURRENT_TEST: rpl.rpl_semi_sync_event_after_sync mysqltest: At line 1: query 'set global rpl_semi_sync_master_wait_point=AFTER_SYNC' failed: 1193: Unknown system variable 'rpl_semi_sync_master_wait_point'
The result from queries just before the failure was: set global rpl_semi_sync_master_wait_point=AFTER_SYNC;
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
to '/usr/share/mysql-test/var/log/rpl.rpl_semi_sync_event_after_sync-mix,xtradb/'
_______________________________________
rpl.sec_behind_master-5114 'stmt' w4 [ fail ] Test ended at 2017-01-21 15:10:24
CURRENT_TEST: rpl.sec_behind_master-5114 mysqltest: In included file "./include/rpl_init.inc": included from ./include/master-slave.inc at line 38: included from /usr/share/mysql-test/suite/rpl/t/sec_behind_master-5114.test at line 1: At line 165: query 'SET GLOBAL gtid_slave_pos= ""' failed: 1198: This operation cannot be performed as you have a running slave ''; run STOP SLAVE '' first
The result from queries just before the failure was: include/master-slave.inc
- saving '/usr/share/mysql-test/var/4/log/rpl.sec_behind_master-5114-stmt/' to '/usr/share/mysql-test/var/log/rpl.sec_behind_master-5114-stmt/' _______________________________________
rpl.rpl_ip_mix w2 [ fail ] Test ended at 2017-01-21 15:11:52
CURRENT_TEST: rpl.rpl_ip_mix mysqltest: In included file "./include/rpl_ip_mix.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix.test at line 11: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix/' rpl.rpl_ip_mix2 w2 [ fail ] Test ended at 2017-01-21 15:11:52
CURRENT_TEST: rpl.rpl_ip_mix2 mysqltest: In included file "./include/rpl_ip_mix2.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ip_mix2.test at line 11: At line 4: query 'connect slave,$IPv6,root,,test,$SLAVE_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,127.0.0.1,root,,test,MASTER_MYPORT); connect (slave,::1,root,,test,SLAVE_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ip_mix2/' to '/usr/share/mysql-test/var/log/rpl.rpl_ip_mix2/' rpl.rpl_ipv4_as_ipv6 w2 [ pass ] 55 rpl.rpl_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:11:56
CURRENT_TEST: rpl.rpl_ipv6 mysqltest: In included file "./include/rpl_ipv6.inc": included from /usr/share/mysql-test/suite/rpl/t/rpl_ipv6.test at line 13: At line 2: query 'connect master,$IPv6,root,,test,$MASTER_MYPORT' failed: 2003: Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")
The result from queries just before the failure was: #################### IP: ::1 ########################### connect (master,::1,root,,test,MASTER_MYPORT);
- saving '/usr/share/mysql-test/var/2/log/rpl.rpl_ipv6/' to '/usr/share/mysql-test/var/log/rpl.rpl_ipv6/' _______________________________________
sys_vars.sysvars_server_notembedded '64bit' w2 [ fail ] Test ended at 2017-01-21 15:12:32
CURRENT_TEST: sys_vars.sysvars_server_notembedded --- /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result 2017-01-17 20:38:24.000000000 +0100 +++ /usr/share/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.reject 2017-01-21 15:12:32.120425458 +0100 mysqltest: Result length mismatch - saving '/usr/share/mysql-test/var/2/log/sys_vars.sysvars_server_notembedded-64bit/'
to '/usr/share/mysql-test/var/log/sys_vars.sysvars_server_notembedded-64bit/'
_______________________________________
main.ipv4_and_ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:38
CURRENT_TEST: main.ipv4_and_ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv4_and_ipv6.test at line 7: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 Output from before failure: _______________________________________
main.ipv6 w2 [ fail ] Test ended at 2017-01-21 15:12:39
CURRENT_TEST: main.ipv6 /usr/bin/mysqladmin: connect to server at '::1' failed error: 'Can't connect to MySQL server on '::1' (99 "Cannot assign requested address")' Check that mysqld is running on ::1 and that the port is 16060. You can check this by doing 'telnet ::1 16060' mysqltest: In included file "/usr/share/mysql-test/include/ipv6_clients.inc": included from /usr/share/mysql-test/t/ipv6.test at line 14: At line 1: exec of '/usr/bin/mysqladmin --defaults-file=/usr/share/mysql-test/var/2/my.cnf --default-character-set=latin1 -h ::1 -P 16060 -u root ping ' failed, error: 256, status: 1, errno: 2 _______________________________________
main.mysql_client_test_nonblock w3 [ fail ] Test ended at 2017-01-21 15:13:46
CURRENT_TEST: main.mysql_client_test_nonblock mysqltest: At line 18: exec of '/usr/bin/mysql_client_test --defaults-file=/usr/share/mysql-test/var/3/my.cnf --testcase --vardir=/usr/share/mysql-test/var/3 --non-blocking-api --getopt-ll-test=25600M >> /usr/share/mysql-test/var/3/log/mysql_client_test.out.log 2>&1' failed, error: 256, status: 1, errno: 2 Output from before failure: call mtr.add_suppression(" Error reading file './client_test_db/test_frm_bug.frm'"); _______________________________________
main.multi_update 'xtradb' w2 [ fail ] Test ended at 2017-01-21 15:14:10
CURRENT_TEST: main.multi_update --- /usr/share/mysql-test/r/multi_update.result 2017-01-17 20:38:20.000000000 +0100 +++ /usr/share/mysql-test/r/multi_update.reject 2017-01-21 15:14:09.912153479 +0100 @@ -1055,7 +1055,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. UPDATE (SELECT 128 as col1) x, table_11757486 SET field1=x.col1; ERROR 22003: Out of range value for column 'field1' at row 1 UPDATE table_11757486 SET field1=128; @@ -1069,7 +1068,6 @@ Warnings: Warning 1264 Out of range value for column 'field1' at row 1 Warning 1264 Out of range value for column 'field1' at row 2 -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. UPDATE IGNORE is unsafe because the order in which rows are updated determines which (if any) rows are ignored. This order cannot be predicted and may differ on master and the slave. DROP TABLE table_11757486; SET SESSION SQL_MODE=default; end of 10.0 tests
mysqltest: Result length mismatch _______________________________________
main.set_statement_notembedded_binlog w2 [ fail ] Test ended at 2017-01-21 15:14:33
CURRENT_TEST: main.set_statement_notembedded_binlog --- /usr/share/mysql-test/r/set_statement_notembedded_binlog.result 2017-01-17 20:38:21.000000000 +0100 +++ /usr/share/mysql-test/r/set_statement_notembedded_binlog.reject 2017-01-21 15:14:33.553868145 +0100 @@ -34,23 +34,10 @@ f1() 1113 111313 -Warnings: -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly. -Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. show binlog events limit 16, 100; _______________________________________
main.view w3 [ fail ] Test ended at 2017-01-21 15:15:15
CURRENT_TEST: main.view mysqltest: At line 5501: query 'alter table v1 check partition p1' failed: 1289: The 'partitioning' feature is disabled; you need MariaDB built with '--with-plugin-partition' to have it working _______________________________________
maria.encrypt-wrong-key w3 [ fail ] Test ended at 2017-01-21 15:15:24
CURRENT_TEST: maria.encrypt-wrong-key
Server [mysqld.1 - pid: 30821, winpid: 30821, exit: 512] failed during test run Server log from this test: ----------SERVER LOG START----------- 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Normal shutdown
2017-01-21 15:15:23 139933618535168 [Note] Event Scheduler: Purging the queue. 0 events 2017-01-21 15:15:23 139933618535168 [Note] /usr/libexec/mysqld: Shutdown complete
2017-01-21 15:15:24 139668697172288 [Note] /usr/libexec/mysqld (mysqld 10.1.21-MariaDB) starting as process 30823 ... 2017-01-21 15:15:24 139668697172288 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162) 2017-01-21 15:15:24 139668697172288 [ERROR] Can't open shared library '/usr/lib64/mysql/plugin/file_key_management.so' (errno: 2, cannot open shared object file: No such file or directory) _______________________________________
Am 21.01.2017 um 14:28 schrieb Elena Stepanova:
Hi Reindl,
On 01/21/2017 05:11 AM, Reindl Harald wrote:
Am 20.01.2017 um 22:58 schrieb Elena Stepanova:
Hi Reindl,
On 01/20/2017 06:03 PM, Reindl Harald wrote:
shouldn't the testsuite at some point in time run without errors?
The testsuite should run without errors with some combinations of build/run server options which it's tuned for and which we normally run it with.
Unfortunately, with arbitrary non-default options in general MTR cannot be guaranteed to run successfully, it's just not that kind of tool. Some problems are easy to fix though, and we'll do it whenever we can. Please in future just file bug reports right away, no need to suffer for years. We can only fix something that we are aware of.
"run STOP SLAVE '' first" - uhm did i start it? it's scripted by shipped scripts
It happens because of --mysqld=--binlog-format=mixed on the command line, more specifically due to a non-clean exit of a previous test which realizes too late that binlog format has been overridden from a command line, and skips the rest of execution, including the clean-up
well, with --mysqld=--binlog-format=mixed at least it did somehow finish at all, i started it without at 7:00 PM as i left home, i came back home 10 minutes ago (4:00 AM) and it still did not finish
but maybe that's just because the new encryption features where the test-suite just don't realize that they are not built and insetad sakip them all togehter it waits for every peice 3 seconds
Well, some failures can prolong the torture, but really it's probably a combination of factors. Still, 9 hours is very long even for a worst-case scenario, so it would be interesting to look at the full MTR output to understand what's happening.
Without seeing it, importantly execution times of successful tests, I can only guess, but if binlog_format setting was the only thing that changed between the runs, and if you always run with '--max-test-fail=0 --force', most likely the culprit is the execution time of rpl suite, worsened by general low performance.
rpl is the longest suite of all, and since it's running in full now, it can take a lot of time (which is why I agree that running tests with only one binlog_format is a reasonable demand). Before, when you ran tests with '--mysqld=--binlog-format=mixed', a big part of this suite and parts of some other suites either were skipped or failed.
You are running tests on disk, rather than in memory. Latency for on-disk runs can be quite bad, depending on the machine. Replication tests in particular are quite sensitive to this. Here is an example from my laptop:
on disk: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 41647 in memory: rpl.rpl_partition_innodb 'mix,xtradb' [ pass ] 251
The fact that tests run without parallel also doesn't help. If you have enough memory, it's worth considering parallel execution -- every test will take longer, but the overall duration might decrease significantly.
Regards, Elena
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb-page_encryption-cbc,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-page_encryption
2017-01-20 19:01:51 140487478450496 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:51 140487478450496 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7618, winpid: 7618, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7641, winpid: 7641, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7646, winpid: 7646, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7651, winpid: 7651, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7656, winpid: 7656, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7661, winpid: 7661, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7666, winpid: 7666, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7701, winpid: 7701, exit: 1792] died after mysql-test-run waited 2.9 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. encryption.innodb_page_encryption_key_change 'cbc,xtradb' [ fail ] Test ended at 2017-01-20 19:02:05
CURRENT_TEST: encryption.innodb_first_page CURRENT_TEST: encryption.innodb-log-encrypt CURRENT_TEST: encryption.innodb-page_encryption_log_encryption CURRENT_TEST: encryption.innodb-missing-key CURRENT_TEST: encryption.innodb_encryption_row_compressed CURRENT_TEST: encryption.innodb_encryption_filekeys CURRENT_TEST: encryption.innodb_encryption_is CURRENT_TEST: encryption.innochecksum CURRENT_TEST: encryption.innodb-bad-key-change CURRENT_TEST: encryption.innodb-discard-import CURRENT_TEST: encryption.innodb-discard-import-change CURRENT_TEST: encryption.innodb-encr-threads CURRENT_TEST: encryption.innodb-encryption-alter CURRENT_TEST: encryption.innodb-page_encryption CURRENT_TEST: encryption.innodb_page_encryption_key_change
Failed to start mysqld.1
- skipping '/usr/share/mysql-test/var/log/encryption.innodb_page_encryption_key_change-cbc,xtradb/'
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7724, winpid: 7724, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. ***Warnings generated in error logs during shutdown after running tests: encryption.innodb_page_encryption_key_change
2017-01-20 19:01:55 140380436027712 [ERROR] /usr/libexec/mysqld: unknown variable 'file-key-management-encryption-algorithm=aes_cbc' 2017-01-20 19:01:55 140380436027712 [ERROR] Aborting
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7747, winpid: 7747, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7770, winpid: 7770, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7793, winpid: 7793, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7817, winpid: 7817, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7840, winpid: 7840, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7863, winpid: 7863, exit: 1792] died after mysql-test-run waited 3.2 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7886, winpid: 7886, exit: 1792] died after mysql-test-run waited 3.1 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created. worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 7909, winpid: 7909, exit: 1792] died after mysql-test-run waited 0.3 seconds for /usr/share/mysql-test/var/run/mysqld.1.pid to be created.
^C Sitzung beendet, Shell wird abgewürgt ?wrong class (hack attempt?): $VAR1 = \undef; $VAR2 = ' 1234My::Test
main.mysql_client_testname in_overlay mysql_client_test shortname &--plugin-load-add=$AUTH_TEST_PLUGIN_SO slave_opt ./usr/share/mysql-test/t/mysql_client_test.testpath &--plugin-load-add=$AUTH_TEST_PLUGIN_SO --general-log 3--general-log-file=$MYSQLTEST_VARDIR/log/master.log --log-output=FILE,TABLE --max-allowed-packet=32000000 master_opt template_pathMy::Suite::Main /usr/share/mysql-test/rrdiropts mainnameX
derived_view show_explain_non_select events_stress func_hybrid_type
myisam_mrr cast
signal_code
change_user innodb_mysql_lock sp-prelocking order_by_sortkey mdl_sync mysqld--defaults-file
events_bugs tmp_table_count-7586 udf_debug_sync multi_statement
parser_stack func_if unsafe_binlog_innodb bool ctype_cp1250_ch mysqltest
ctype_ldml lock mysqld_option_err sp-code ?myisam_enable_keys-10506 information_schema_db ctype_gbk_binlog odbc variables tablelock join_outer_innodb dyncol
debug_sync
join_nested
sighup-6580 func_test truncate_coverage group_min_max bug58669 mysql_locale_posix
ipv4_as_ipv6 gis-rt-precise varbinary key fulltext3 kill_processlist-6619 myisam_crash_before_flush_keys trigger_null-8605 ps_4heap
mysqlbinlog get_diagnostics
select_safe \\0'; ^C ? abgewürgt.
participants (3)
-
Elena Stepanova
-
Reindl Harald
-
Sergei Golubchik