Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL)
-
None
Description
When the server fails to start at the beginning of a test, the corresponding MTR worker immediately aborts, doesn't finalize the test and doesn't run any other ones.
As a result,
- failures aren't recorded in final results or in the buildbot database;
- if all parallel workers abort this way, the test suite execution aborts prematurely.
$ cat /data/bug/1.test
|
select 1;
|
|
$ cat /data/bug/1.cnf
|
!include include/default_my.cnf
|
|
[mysqld.1]
|
foo
|
$ perl ./mtr bug.1 main.1st --noreorder --force --max-test-fail=0
|
10.2 2df99f21 (bad) |
==============================================================================
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
|
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 2668675, winpid: 2668675] died after mysql-test-run waited 0.2 seconds for /mnt-hd8t/bld/10.2-debug-nightly/mysql-test/var/run/mysqld.1.pid to be created.
|
worker[1] mysql-test-run: *** ERROR: Failed to start mysqld mysqld.1 with command /mnt-hd8t/bld/10.2-debug-nightly/bin/mysqld --defaults-group-suffix=.1 --defaults-file=/mnt-hd8t/bld/10.2-debug-nightly/mysql-test/var/my.cnf --log-output=file --core-file --loose-debug-sync-timeout=300
|
mysql-test-run: *** ERROR: Test suite aborted
|
The desired result is of course that the test is marked as failed and execution of the test suite continues normally, like this:
10.2.37 (good) |
==============================================================================
|
|
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
|
worker[1] Using MTR_BUILD_THREAD 301, with reserved ports 16020..16039
|
select 1;
|
1
|
1
|
bug.2 [ fail ]
|
Test ended at 2021-11-04 16:20:03
|
|
CURRENT_TEST: bug.2
|
|
|
Server [mysqld.1 - pid: 2669220, winpid: 2669220, exit: 512] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
2021-11-04 16:20:02 139846509990656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (mysqld 10.2.37-MariaDB-debug-log) starting as process 2669205 ...
|
2021-11-04 16:20:02 139846509990656 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32198)
|
2021-11-04 16:20:02 139846509990656 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'SEQUENCE' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'partition' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'InnoDB' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_LOCKS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMPMEM' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'FEEDBACK' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'user_variables' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TRX' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_METRICS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2021-11-04 16:20:02 139846509990656 [Warning] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--loose-pam-debug'
|
2021-11-04 16:20:02 139846509990656 [Note] Server socket created on IP: '127.0.0.1'.
|
2021-11-04 16:20:02 139846509990656 [Note] Reading of all Master_info entries succeeded
|
2021-11-04 16:20:02 139846509990656 [Note] Added new Master_info '' to hash table
|
2021-11-04 16:20:02 139846509990656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: ready for connections.
|
Version: '10.2.37-MariaDB-debug-log' socket: '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/tmp/mysqld.1.sock' port: 16020 Source distribution
|
2021-11-04 16:20:02 139846330197760 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
|
2021-11-04 16:20:02 139846330197760 [Note] Event Scheduler: Purging the queue. 0 events
|
2021-11-04 16:20:02 139846330197760 [Note] Debug sync points hit: 855
|
2021-11-04 16:20:02 139846330197760 [Note] Debug sync points executed: 0
|
2021-11-04 16:20:02 139846330197760 [Note] Debug sync points max active per thread: 0
|
2021-11-04 16:20:02 139846330197760 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: Shutdown complete
|
|
2021-11-04 16:20:03 140490684326656 [Note] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld (mysqld 10.2.37-MariaDB-debug-log) starting as process 2669221 ...
|
2021-11-04 16:20:03 140490684326656 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32198)
|
2021-11-04 16:20:03 140490684326656 [Warning] Changed limits: max_open_files: 1024 max_connections: 151 (was 151) table_cache: 421 (was 2000)
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'SEQUENCE' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'partition' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'InnoDB' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_LOCKS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_MUTEXES' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMPMEM' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_PER_INDEX' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'FEEDBACK' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'user_variables' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TRX' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_METRICS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_VIRTUAL' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
|
2021-11-04 16:20:03 140490684326656 [Warning] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--loose-pam-debug'
|
2021-11-04 16:20:03 140490684326656 [ERROR] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--foo'
|
2021-11-04 16:20:03 140490684326656 [ERROR] Aborting
|
|
----------SERVER LOG END-------------
|
mysqltest failed but provided no output
|
|
|
- saving '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/log/bug.2/' to '/mnt-hd8t/bld/10.2.37-asan/mysql-test/var/log/bug.2/'
|
***Warnings generated in error logs during shutdown after running tests: bug.2
|
|
2021-11-04 16:20:03 140490684326656 [ERROR] /mnt-hd8t/bld/10.2.37-asan/bin/mysqld: unknown option '--foo'
|
2021-11-04 16:20:03 140490684326656 [ERROR] Aborting
|
|
main.1st [ pass ] 2
|
--------------------------------------------------------------------------
|
The servers were restarted 1 times
|
Spent 0.002 of 6 seconds executing testcases
|
|
Completed: Failed 1/2 tests, 50.00% were successful.
|
|
Failing test(s): bug.2
|
|
The log files in var/log may give you some hint of what went wrong.
|
|
If you want to report this error, please read first the documentation
|
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
|
|
Errors/warnings were found in logfiles during server shutdown after running the
|
following sequence(s) of tests:
|
bug.2
|
mysql-test-run: *** ERROR: there were failing test cases
|
It is (partially) a regression introduced by this commit
commit feacc0aaf2860a391f0febbc11e42f1d09598705 (HEAD)
|
Author: Sergei Golubchik
|
Date: Mon Jan 25 13:16:04 2021 +0100
|
|
unify mtr handling of debuggers
|
particularly by this change
@@ -5455,11 +5120,8 @@ sub mysqld_start ($$) {
|
mtr_verbose("Started $mysqld->{proc}");
|
}
|
|
- if ( $wait_for_pid_file &&
|
- !sleep_until_file_created($mysqld->value('pid-file'),
|
- $opt_start_timeout,
|
- $mysqld->{'proc'},
|
- $warn_seconds))
|
+ if (!sleep_until_file_created($mysqld->value('pid-file'),
|
+ $opt_start_timeout, $mysqld->{'proc'}, $warn_seconds))
|
{
|
my $mname= $mysqld->name();
|
mtr_error("Failed to start mysqld $mname with command $exe");
|
That's where the worker aborts.
Before the change, $wait_for_pid_file would be true for all debuggers, but false for the "normal" (non-debugging) execution. Apparently it was a very intentional distinction.
Later when rr was introduced, it inherited logic of debuggers, so it would abort with rr execution too, I'm not sure whether it was intentional or not.
But now the logic is unified and the $wait_for_pid_file variable has gone away, so it always aborts, even for normal execution, hence the effects described earlier.
I can de-unify it by introducing a flag based on the initial MTR call options, but maybe it's more consistent to do something about it in My::Debugger (to make the distinction when the execution should be aborted and when it should continue).