Bug #87279 Error log pattern searches broken in main.mysql_upgrade_test
Submitted: 2 Aug 2017 7:46 Modified: 8 Aug 2017 13:06
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Server Severity:S3 (Non-critical)
Version:8.0.2 OS:Any
Assigned to: CPU Architecture:Any
Tags: mtr

[2 Aug 2017 7:46] Laurynas Biveinis
Description:
Several parts of main.mysql_upgrade_grant test search the server error log for expected patterns. But they do so without restarting the server with some custom error log path, as a result, the log contains everything from the MTR run on the same worker so far.

This is bad because now the searches can find output of the preceding tests. This breaks --repeat option, retry on failure, and should any previous test caused same output in the server log, the corresponding part of the test stops working and just passes silently.

How to repeat:
1) Copy main.mysql_upgrade_grant to main.mysql_upgrade_grant2:
$ cd mysql-test/
$ cp t/mysql_upgrade_grant.test t/mysql_upgrade_grant2.test
$ cp r/mysql_upgrade_grant.result r/mysql_upgrade_grant2.result

2) Break mysql_upgrade_grant2 test intentionally by removing the command which later causes the expected error log output:

$ diff -u t/mysql_upgrade_grant.test t/mysql_upgrade_grant2.test 
--- t/mysql_upgrade_grant.test	2017-06-27 14:00:43.000000000 +0300
+++ t/mysql_upgrade_grant2.test	2017-08-02 10:17:20.000000000 +0300
@@ -52,9 +52,9 @@
 --source include/user_58_to_57.inc
 --source include/user_57_to_56.inc
 
-INSERT INTO mysql.user VALUES
-('localhost','B19011337_nhash','*46ABF58B20022A84DF7B2E8B1AC8219C8DA71553','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N'),
-('localhost','B19011337_ohash','0f0ea7602c473904','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N');
+# INSERT INTO mysql.user VALUES
+# ('localhost','B19011337_nhash','*46ABF58B20022A84DF7B2E8B1AC8219C8DA71553','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N'),
+# ('localhost','B19011337_ohash','0f0ea7602c473904','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N');
 
 call mtr.add_suppression("Some of the user accounts with SUPER");
 call mtr.add_suppression("1. Stop");
@@ -96,14 +96,14 @@
 --exec $MYSQL_UPGRADE --skip-verbose --force 2>&1
 
 --echo # expect mysql_native_password
-SELECT plugin FROM mysql.user WHERE user='B19011337_nhash';
+# SELECT plugin FROM mysql.user WHERE user='B19011337_nhash';
 
 --echo # expect empty plugin
-SELECT plugin FROM mysql.user WHERE user='B19011337_ohash';
+# SELECT plugin FROM mysql.user WHERE user='B19011337_ohash';
 
 --echo # cleanup
-DROP USER B19011337_nhash@localhost;
-DROP USER B19011337_ohash@localhost;
+# DROP USER B19011337_nhash@localhost;
+# DROP USER B19011337_ohash@localhost;
 
 # Restore the saved contents of mysql.user and mysql.tables_priv
 --let $restore= 1

$ diff -u r/mysql_upgrade_grant.result r/mysql_upgrade_grant2.result
--- r/mysql_upgrade_grant.result	2017-06-27 14:00:43.000000000 +0300
+++ r/mysql_upgrade_grant2.result	2017-08-02 10:26:51.000000000 +0300
@@ -110,9 +110,6 @@
 ALTER TABLE mysql.user DROP COLUMN password_last_changed;
 ALTER TABLE mysql.user DROP COLUMN password_lifetime;
 ALTER TABLE mysql.user DROP COLUMN account_locked;
-INSERT INTO mysql.user VALUES
-('localhost','B19011337_nhash','*46ABF58B20022A84DF7B2E8B1AC8219C8DA71553','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N'),
-('localhost','B19011337_ohash','0f0ea7602c473904','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','Y','','','','',0,0,0,0,'','','N');
 call mtr.add_suppression("Some of the user accounts with SUPER");
 call mtr.add_suppression("1. Stop");
 call mtr.add_suppression("2. Run");
@@ -126,7 +123,6 @@
 # let's check for the presense of the warning
 # end of check for the presense of the warning
 # repair the user's plugin
-mysql_upgrade: (non fatal) [WARNING] 1642: Pre-4.1 password hash found. It is deprecated and will be removed in a future release. Please upgrade it to a new format.
 mysql.columns_priv                                 OK
 mysql.component                                    OK
 mysql.db                                           OK
@@ -166,16 +162,8 @@
 mtr.test_suppressions                              OK
 sys.sys_config                                     OK
 # expect mysql_native_password
-SELECT plugin FROM mysql.user WHERE user='B19011337_nhash';
-plugin
-mysql_native_password
 # expect empty plugin
-SELECT plugin FROM mysql.user WHERE user='B19011337_ohash';
-plugin
-
 # cleanup
-DROP USER B19011337_nhash@localhost;
-DROP USER B19011337_ohash@localhost;
 TRUNCATE TABLE mysql.tables_priv;
 INSERT INTO mysql.tables_priv (SELECT * FROM mysql.tmp_backup_tables_priv);
 DROP TABLE mysql.tmp_backup_tables_priv;

3) Verify that the test is broken by missing error log output:

$ ./mtr --debug-server mysql_upgrade_grant2
...
main.mysql_upgrade_grant2                [ fail ]
        Test ended at 2017-08-02 10:37:54

CURRENT_TEST: main.mysql_upgrade_grant2
# ERROR: The file '/Users/laurynas/percona/obj-mysql-8.0.2-asan-debug-openssl/mysql-test/var/log/mysqld.1.err' does not contain the expected pattern  User entry 'B19011337_ohash'@'localhost' has a deprecated pre-4.1 password. The user will be ignored and no one can login with this user anymore.
-><-
mysqltest: In included file ./include/search_pattern_in_file.inc at line 74:
included from /Users/laurynas/percona/mysql-8.0.2/mysql-test/t/mysql_upgrade_grant2.test at line 78:
At line 57: command "perl" failed with error 255. my_errno=2

4) Now run mysql_upgrade_grant followed by mysql_upgrade_grant2, and see a false positive pass:

$ ./mtr --debug-server mysql_upgrade_grant mysql_upgrade_grant2
...
main.mysql_upgrade_grant                 [ pass ]  236993
main.mysql_upgrade_grant2                [ pass ]  246627
...

Suggested fix:
Restart the server at the start of the testcase with custom error log, grep that, restart again at the end with the default log, remove the custom log.
[2 Aug 2017 8:49] Umesh Shastry
Hello Laurynas,

Thank you for the report.

Thanks,
Umesh
[5 Aug 2017 7:29] Laurynas Biveinis
Bug 87279 fix for 8.0.2

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug87279-8.0.2.patch (application/octet-stream, text), 5.33 KiB.

[8 Aug 2017 13:06] Paul Dubois
Posted by developer:
 
Fixed in 8.0.3.

The main.mysql_upgrade_grant, main.roles-upgrade, and
auth_sec.secure_file_priv_warnings, test cases mishandled the error
log. Thanks to Laurynas Biveinis for the patch.