maria-developers team mailing list archive

Thread
Date
Re: 01612f594b3: MDEV-23769: MTR can abort before it prints the test result summary

To: Anel Husakovic <anel@xxxxxxxxxxx>
From: Sergei Golubchik <serg@xxxxxxxxxxx>
Date: Thu, 22 Oct 2020 10:39:32 +0200
Cc: maria-developers@xxxxxxxxxxxxxxxxxxx
In-reply-to: <2R7UKl5ACqJ.A.u7H.UHUkfB@pweza>
Hi, Anel!

On Oct 22, Anel Husakovic wrote:
> revision-id: 01612f594b3 (mariadb-10.1.43-300-g01612f594b3)
> parent(s): 82301aea4f2
> author: Anel Husakovic <anel@xxxxxxxxxxx>
> committer: Anel Husakovic <anel@xxxxxxxxxxx>
> 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@xxxxxxxxxxx