[#MDEV-26972] MTR worker aborts after server restart failure

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,

$ 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

commit feacc0aaf2860a391f0febbc11e42f1d09598705 (HEAD)

Author: Sergei Golubchik

Date:   Mon Jan 25 13:16:04 2021 +0100

    unify mtr handling of debuggers

@@ -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).

[MDEV-26972] MTR worker aborts after server restart failure Created: 2021-11-04 Updated: 2021-12-10 Resolved: 2021-11-26
Status:	Closed
Project:	MariaDB Server
Component/s:	Scripts & Clients, Tests
Affects Version/s:	10.2, 10.3, 10.4, 10.5, 10.6, 10.7
Fix Version/s:	10.2.42, 10.3.33, 10.4.23, 10.5.14, 10.6.6

[MDEV-26972] MTR worker aborts after server restart failure Created: 2021-11-04 Updated: 2021-12-10 Resolved: 2021-11-26