Re: [Maria-developers] 01612f594b3: MDEV-23769: MTR can abort before it prints the test result summary

Hi, Anel! On Oct 22, Anel Husakovic wrote:

revision-id: 01612f594b3 (mariadb-10.1.43-300-g01612f594b3) parent(s): 82301aea4f2 author: Anel Husakovic committer: Anel Husakovic timestamp: 2020-10-03 02:34:03 +0200 message:

MDEV-23769: MTR can abort before it prints the test result summary

- Patch is solving generating report on warning - Patch is doing cosmetic fix of `current_test` log file which holds the old log value of test `CURRENT TEST:..` in `mark_log()` in case of `unknown option` and as such the logic which is using it's content doesn't output valid log content and doesn't generate valid `$test->{'comment'}` message.

more is not always better. please remove everything in the commit comment below this line - 400 lines that don't explain anything beyond what your *one line* of the comment already did. And now you have to press PageDown many times to get to my main comment about the fix :)

Here are the test cases observed. Note that only in 6. scenario there is `print $child "HELLO\n";` problem in printing (to delete?).

1. Valid test case, but warning in server log ``` $ ./mtr MDEV-23769 --force Logging: ./mtr MDEV-23769 --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 show databases; Database information_schema mtr mysql performance_schema test main.MDEV-23769 [ fail ] Found warnings/errors in server log file! Test ended at 2020-10-03 02:13:00 line 2020-10-03 2:13:00 140309996242496 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 ^ Found warnings in /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/mysqld.1.err ok

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' -------------------------------------------------------------------------- The servers were restarted 0 times Spent 0.000 of 4 seconds executing testcases mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/warnings' for details.

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.MDEV-23769

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

mysql-test-run: *** ERROR: there were failing test cases ```

2. Valid test cases (same), but warning in server log (Note reported single test case) ``` $ ./mtr MDEV-23769 MDEV-23769 --force Logging: ./mtr MDEV-23769 MDEV-23769 --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 show databases; Database information_schema mtr mysql performance_schema test main.MDEV-23769 [ fail ] Found warnings/errors in server log file! Test ended at 2020-10-03 02:15:05 line 2020-10-03 2:15:04 139868136609344 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 ^ Found warnings in /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/mysqld.1.err ok

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' show databases; Database information_schema mtr mysql performance_schema test main.MDEV-23769 [ fail ] Found warnings/errors in server log file! Test ended at 2020-10-03 02:15:05 line 2020-10-03 2:15:05 140513782085184 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 ^ Found warnings in /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/mysqld.1.err ok

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' -------------------------------------------------------------------------- The servers were restarted 1 times Spent 0.000 of 5 seconds executing testcases mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/warnings' for details.

Completed: Failed 2/2 tests, 0.00% were successful.

Failing test(s): main.MDEV-23769

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

mysql-test-run: *** ERROR: there were failing test cases ```

3. Valid test cases (different test cases), but warning in server log (Note one passed one failed)

``` $ ./mtr MDEV-23769 1st --force Logging: ./mtr MDEV-23769 1st --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 show databases; Database information_schema mtr mysql performance_schema test main.MDEV-23769 [ fail ] Found warnings/errors in server log file! Test ended at 2020-10-03 02:17:09 line 2020-10-03 2:17:08 140658805515840 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 ^ Found warnings in /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/mysqld.1.err ok

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' main.1st [ pass ] 1 -------------------------------------------------------------------------- The servers were restarted 1 times Spent 0.001 of 4 seconds executing testcases mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/warnings' for details.

Completed: Failed 1/2 tests, 50.00% were successful.

Failing test(s): main.MDEV-23769

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

mysql-test-run: *** ERROR: there were failing test cases

```

4. Now for example 3. create artificial failure with warnings in server log (note, both test failed)

```

$ ./mtr MDEV-23769 1st --force Logging: ./mtr MDEV-23769 1st --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 show databases; Database information_schema mtr mysql performance_schema test main.MDEV-23769 [ fail ] Found warnings/errors in server log file! Test ended at 2020-10-03 02:17:52 line 2020-10-03 2:17:51 140260493149760 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 ^ Found warnings in /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/mysqld.1.err ok

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' main.1st [ fail ] Test ended at 2020-10-03 02:17:52

CURRENT_TEST: main.1st mysqltest: At line 5: End of line junk detected: "show tables in mysql "

The result from queries just before the failure was: show databases; Database information_schema mtr mysql performance_schema test

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.1st/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.1st/' -------------------------------------------------------------------------- The servers were restarted 1 times Spent 0.000 of 4 seconds executing testcases mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/warnings' for details.

Completed: Failed 2/2 tests, 0.00% were successful.

Failing test(s): main.MDEV-23769 main.1st

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

mysql-test-run: *** ERROR: there were failing test cases

```

5. Generate unknown option, for the same example as 3. (note: both failed) ```

$ ./mtr MDEV-23769 1st --mysqld=--xx --force Logging: ./mtr MDEV-23769 1st --mysqld=--xx --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 52531, winpid: 52531, exit: 512] died after mysql-test-run waited 0.3 seconds for /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/run/mysqld.1.pid to be created. main.MDEV-23769 [ fail ] Test ended at 2020-10-03 02:19:01

CURRENT_TEST: main.MDEV-23769

Failed to start mysqld.1 mysqltest failed but provided no output

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' ***Warnings generated in error logs during shutdown after running tests: main.MDEV-23769

2020-10-03 2:19:01 140238937720384 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 2020-10-03 2:19:01 140238937720384 [ERROR] /home/anel/mariadb/10.1-mtr-in-source/sql/mysqld: unknown option '--xx' 2020-10-03 2:19:01 140238937720384 [ERROR] Aborting

worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 52537, winpid: 52537, exit: 512] died after mysql-test-run waited 0.3 seconds for /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/run/mysqld.1.pid to be created. main.1st [ fail ] Test ended at 2020-10-03 02:19:02

CURRENT_TEST: main.1st

Failed to start mysqld.1 mysqltest failed but provided no output

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.1st/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.1st/' ***Warnings generated in error logs during shutdown after running tests: main.1st

2020-10-03 2:19:02 140048201700928 [ERROR] /home/anel/mariadb/10.1-mtr-in-source/sql/mysqld: unknown option '--xx' 2020-10-03 2:19:02 140048201700928 [ERROR] Aborting

Can't use an undefined value as a symbol reference at ./mtr line 657. -------------------------------------------------------------------------- The servers were restarted 1 times Spent 0.000 of 5 seconds executing testcases

Completed: Failed 2/2 tests, 0.00% were successful.

Failing test(s): main.MDEV-23769 main.1st

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: main.MDEV-23769 main.1st mysql-test-run: *** ERROR: there were failing test cases

```

6. Again the same option, but with 2 same tests -> not perl error: `Can't use an undefined value as a symbol reference at ./mtr line 657. ` ` print $child "HELLO\n";` (solution delete the line).

``` $ ./mtr MDEV-23769 MDEV-23769 --mysqld=--xx --force Logging: ./mtr MDEV-23769 MDEV-23769 --mysqld=--xx --force vardir: /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var'... Checking supported features... MariaDB Version 10.1.47-MariaDB-debug - SSL connections supported - binaries are debug compiled Sphinx 'indexer' binary not found, sphinx suite will be skipped Collecting tests... Installing system database...

==============================================================================

TEST RESULT TIME (ms) or COMMENT --------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 52595, winpid: 52595, exit: 512] died after mysql-test-run waited 0.3 seconds for /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/run/mysqld.1.pid to be created. main.MDEV-23769 [ fail ] Test ended at 2020-10-03 02:20:12

CURRENT_TEST: main.MDEV-23769

Failed to start mysqld.1 mysqltest failed but provided no output

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' ***Warnings generated in error logs during shutdown after running tests: main.MDEV-23769

2020-10-03 2:20:12 139815724283456 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 2020-10-03 2:20:12 139815724283456 [ERROR] /home/anel/mariadb/10.1-mtr-in-source/sql/mysqld: unknown option '--xx' 2020-10-03 2:20:12 139815724283456 [ERROR] Aborting

worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 52601, winpid: 52601, exit: 512] died after mysql-test-run waited 0.3 seconds for /home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/run/mysqld.1.pid to be created. main.MDEV-23769 [ fail ] Test ended at 2020-10-03 02:20:12

CURRENT_TEST: main.MDEV-23769

Failed to start mysqld.1 mysqltest failed but provided no output

- saving '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' to '/home/anel/mariadb/10.1-mtr-in-source/mysql-test/var/log/main.MDEV-23769/' ***Warnings generated in error logs during shutdown after running tests: main.MDEV-23769

2020-10-03 2:20:12 140650797745728 [Warning] option 'lock_wait_timeout': unsigned value 18446744073709551615 adjusted to 31536000 2020-10-03 2:20:12 140650797745728 [ERROR] /home/anel/mariadb/10.1-mtr-in-source/sql/mysqld: unknown option '--xx' 2020-10-03 2:20:12 140650797745728 [ERROR] Aborting

Can't use an undefined value as a symbol reference at ./mtr line 657. -------------------------------------------------------------------------- The servers were restarted 1 times Spent 0.000 of 5 seconds executing testcases

Completed: Failed 2/2 tests, 0.00% were successful.

Failing test(s): main.MDEV-23769

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: main.MDEV-23769 main.MDEV-23769 mysql-test-run: *** ERROR: there were failing test cases

```

diff --git a/mysql-test/disabled.def b/mysql-test/disabled.def index ee30c4f4d3c..fdb62a7e5f5 100644 --- a/mysql-test/disabled.def +++ b/mysql-test/disabled.def @@ -20,3 +20,4 @@ ssl_crl_clrpath : broken upstream file_contents : MDEV-6526 these files are not installed anymore max_statement_time : cannot possibly work, depends on timing partition_open_files_limit : open_files_limit check broken by MDEV-18360 +MDEV-23769 : Intentionally disabled, for validating purposes.

I don't know if it makes any sense. A dead test that nobody will ever run. May be it's better not to add it at all? In the past I've added tests like that too, the "mtr" and "mtr2" suites. I regret it now :) Tests only help if they're run.

diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl index 52920530132..8d761fd70cf 100755 --- a/mysql-test/mysql-test-run.pl +++ b/mysql-test/mysql-test-run.pl @@ -1005,6 +1005,13 @@ sub run_worker ($) { stop_servers(reverse all_servers()); if(check_warnings_post_shutdown($server)) { # Warnings appeared in log file(s) during final server shutdown. + # Make sure first to run statistics + my $tests= collect_test_cases($opt_reorder, $opt_suites, \@opt_cases, \@opt_skip_test_list); + my ($prefix, $fail, $completed, $extra_warnings)= + run_test_server($server, $tests, $opt_parallel); + mtr_print_line(); + print_total_times($opt_parallel) if $opt_report_times; + mtr_report_stats($prefix, $fail, $completed, $extra_warnings);

I don't understand the fix. You're saying that if a warning happens on shutdown then mtr won't print the result summary. This doesn't seem to be the case, I've tried few times to repeat it - modified mtr to always pretend there's a warning on shutdown, and modified mysqld to always issue a warning on shutdown - and in all cases I saw the result summary all right.

exit(1); } } @@ -3971,6 +3978,7 @@ sub run_testcase ($$) { if (start_servers($tinfo)) { report_failure_and_restart($tinfo); + unlink $path_current_testlog; return 1; } } diff --git a/mysql-test/t/MDEV-23769.opt b/mysql-test/t/MDEV-23769.opt new file mode 100644 index 00000000000..fd8dbcab53f --- /dev/null +++ b/mysql-test/t/MDEV-23769.opt @@ -0,0 +1 @@ +--lock-wait-timeout=-1 diff --git a/mysql-test/t/MDEV-23769.test b/mysql-test/t/MDEV-23769.test new file mode 100644 index 00000000000..9938c7cf644 --- /dev/null +++ b/mysql-test/t/MDEV-23769.test @@ -0,0 +1,4 @@ +--echo # +--echo # MDEV-23769: MTR can abort before it prints the test result summary +--echo # +show databases;

Regards, Sergei VP of MariaDB Server Engineering and security@mariadb.org