PS-9611 fix: Assertion '!is_set() || m_can_overwrite_status' failure while server shutdown (8.0)

components/masking_functions/include/masking_functions/server_helpers.hpp

@@ -18,6 +18,8 @@
 
 #include <functional>
 
+class THD;
+
 namespace masking_functions {
 
 using lock_protected_function = std::function<void()>;
@@ -31,6 +33,10 @@ using lock_protected_function = std::function<void()>;
 // this function may throw if 'func' throws
 bool execute_under_lock_if_not_in_shutdown(const lock_protected_function &func);
 
+void reset_thd_diagnostic_area(THD *thd);
+
+bool is_connection_events_loop_aborted();
+
 }  // namespace masking_functions
 
 #endif  // MASKING_FUNCTIONS_SERVER_HELPERS_HPP

components/masking_functions/src/masking_functions/dictionary_flusher_thread.cpp

@@ -327,7 +327,14 @@ void dictionary_flusher_thread::do_periodic_reload() {
   assert(extracted_thd != nullptr);
 
   const auto is_terminated_lambda{[thd = extracted_thd, this]() {
-    if ((*is_killed_hook)(thd) != 0) {
+    // Any of the following conditions must set Flusher thread state to
+    // 'stopped':
+    // 1. Thread is killed - "(*is_killed_hook)(thd) != 0"
+    // 2. Server received a SIGTERM / SIGQUIT signal -
+    //    "connection_events_loop_aborted()"
+    // 3. Shutdown started - "srv_session_server_is_available() == 0"
+    if ((*is_killed_hook)(thd) != 0 || is_connection_events_loop_aborted() ||
+        srv_session_server_is_available() == 0) {
       state_.store(state_type::stopped);
     }
     return state_.load() == state_type::stopped;
@@ -359,6 +366,24 @@ void dictionary_flusher_thread::do_periodic_reload() {
 
       failure_message.reset();
       try {
+        // In rare cases when this thread is in the middle of execution of
+        // its dictionary table SELECT statement, the server may receive a
+        // SHUTDOWN command and will start the shutdown process causing this
+        // SELECT statement to fail. This situation is properly handled by
+        // the 'mysql_command_xxx' services, and this SELECT will terminate
+        // with the 'execution aborted because of the server shutdown'
+        // status. However, in this scenario this status is not cleared in
+        // the diagnostic area of the THD object.
+        // Before recent changes to 'is_terminated_lambda' (adding
+        // 'is_connection_events_loop_aborted()' to the list of external
+        // termination conditions) a scenario was possible when we didn't
+        // detect flusher thread termination in time and tried to execute the
+        // same SELECT statement again, triggering assertion about diagnostic
+        // area of the THD object not being empty.
+        // So, to play extra safe, we call 'reset_thd_diagnostic_area()'
+        // which internally does
+        // "thd->get_stmt_da()->reset_diagnostics_area()" here.
+        reset_thd_diagnostic_area(extracted_thd);
         cache->reload_cache();
       } catch (const std::exception &e) {
         failure_message.emplace(
@@ -377,8 +402,13 @@ void dictionary_flusher_thread::do_periodic_reload() {
       DBUG_EXECUTE_IF("enable_masking_functions_flush_thread_sync", {
         DEBUG_SYNC(extracted_thd, "masking_functions_after_cache_reload");
       });
-
-      expires_at = std::chrono::steady_clock::now() + flush_interval_duration;
+      const auto local_now{std::chrono::steady_clock::now()};
+      // no time_point overflow should happen here as max
+      // 'flush_interval_duration' is limited to a reasonable value
+      expires_at = local_now + flush_interval_duration;
+      // NOLINTNEXTLINE(cppcoreguidelines-avoid-do-while)
+      DBUG_EXECUTE_IF("enable_masking_functions_flush_thread_turbo_mode",
+                      { expires_at = local_now; });
     } else {
       std::this_thread::sleep_for(sleep_interval);
     }

components/masking_functions/src/masking_functions/server_helpers.cpp

@@ -18,6 +18,7 @@
 #include <rwlock_scoped_lock.h>
 
 #include "sql/mysqld.h"
+#include "sql/sql_class.h"
 
 namespace masking_functions {
 
@@ -34,4 +35,12 @@ bool execute_under_lock_if_not_in_shutdown(
   return true;
 }
 
+void reset_thd_diagnostic_area(THD *thd) {
+  thd->get_stmt_da()->reset_diagnostics_area();
+}
+
+bool is_connection_events_loop_aborted() {
+  return connection_events_loop_aborted();
+}
+
 }  // namespace masking_functions

components/masking_functions/src/masking_functions/sys_vars.cpp

@@ -42,7 +42,10 @@ constexpr const char flush_interval_var_name[]{
     "dictionaries_flush_interval_seconds"};
 
 char default_database_name[]{"mysql"};
-const ulonglong default_flush_interval_seconds = 0;
+constexpr ulonglong min_flush_interval_seconds{0};
+// 1 year = 60 * 60 * 24 * 365 seconds = 31 536 000 seconds
+constexpr ulonglong max_flush_interval_seconds{60ULL * 60ULL * 24ULL * 365ULL};
+constexpr ulonglong default_flush_interval_seconds{min_flush_interval_seconds};
 
 bool is_database_name_initialised = false;
 bool is_flush_interval_initialised = false;
@@ -79,7 +82,9 @@ bool register_sys_vars() {
   is_database_name_initialised = true;
 
   INTEGRAL_CHECK_ARG(ulonglong)
-  check_flush_interval{default_flush_interval_seconds, 0, ULLONG_MAX, 1};
+  check_flush_interval{default_flush_interval_seconds,
+                       min_flush_interval_seconds, max_flush_interval_seconds,
+                       1};
 
   if (services.registrator->register_variable(
           component_name, flush_interval_var_name,

mysql-test/suite/component_masking_functions/r/flusher_thread_da_cleanup.result

@@ -0,0 +1,22 @@
+#
+# PS-9611 "Assertion `!is_set() || m_can_overwrite_status' failure while server shutdown"
+# https://perconadev.atlassian.net/browse/PS-9611
+#
+CALL mtr.add_suppression("Flusher thread terminated while waiting for session server");
+CALL mtr.add_suppression("Exception during reloading dictionary cache");
+CREATE TABLE mysql.masking_dictionaries(
+Dictionary VARCHAR(256) NOT NULL,
+Term VARCHAR(256) NOT NULL,
+UNIQUE INDEX dictionary_term_idx (Dictionary, Term)
+) ENGINE = InnoDB DEFAULT CHARSET=utf8mb4;
+GRANT SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries TO 'mysql.session'@'localhost';
+INSTALL COMPONENT 'file://component_masking_functions';
+# restart:<hidden args>
+include/assert.inc [Turbo mode must be enabled via DBUG]
+include/assert.inc [dictionaries_flush_interval_seconds must be set to 1 year]
+SET debug_sync = 'now SIGNAL masking_functions_before_cache_reload_signal WAIT_FOR masking_functions_after_cache_reload_signal';
+SET debug_sync = 'RESET';
+# restart:<hidden args>
+UNINSTALL COMPONENT 'file://component_masking_functions';
+REVOKE SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries FROM 'mysql.session'@'localhost';
+DROP TABLE mysql.masking_dictionaries;

mysql-test/suite/component_masking_functions/r/sys_var_dictionaries_flush_interval_seconds_basic.result

@@ -1,37 +1,35 @@
 CALL mtr.add_suppression("Flusher thread terminated while waiting for session server");
 CALL mtr.add_suppression("Flusher thread terminated after creating internal connection");
 CALL mtr.add_suppression("Server shutdown requested while attempting to establish flusher thread connection");
+CALL mtr.add_suppression("option 'masking-functions.dictionaries-flush-interval-seconds':.*adjusted");
 INSTALL COMPONENT 'file://component_masking_functions';
-SELECT @@global.masking_functions.dictionaries_flush_interval_seconds;
-@@global.masking_functions.dictionaries_flush_interval_seconds
-0
-SELECT NAME FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%";
-NAME
-SET GLOBAL masking_functions.dictionaries_flush_interval_seconds=100;
+include/assert.inc [default dictionaries_flush_interval_seconds value must be 0]
+include/assert.inc [flusher thread must not be running]
+SET GLOBAL masking_functions.dictionaries_flush_interval_seconds = 100;
 ERROR HY000: Variable 'masking_functions.dictionaries_flush_interval_seconds' is a read only variable
-SET SESSION masking_functions.dictionaries_flush_interval_seconds=100;
+SET SESSION masking_functions.dictionaries_flush_interval_seconds = 100;
 ERROR HY000: Variable 'masking_functions.dictionaries_flush_interval_seconds' is a read only variable
 CREATE TABLE mysql.masking_dictionaries(
 Dictionary VARCHAR(256) NOT NULL,
 Term VARCHAR(256) NOT NULL,
 UNIQUE INDEX dictionary_term_idx (Dictionary, Term)
-) ENGINE = InnoDB DEFAULT CHARSET=utf8mb4;
+) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
 GRANT SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries TO 'mysql.session'@'localhost';
+# restart: --masking_functions.dictionaries_flush_interval_seconds=31536001
+include/assert.inc [setting dictionaries_flush_interval_seconds to a value higher than 31536000 must result in clipping it to 31536000]
+# restart: --masking_functions.dictionaries_flush_interval_seconds=-1
+include/assert.inc [setting dictionaries_flush_interval_seconds to a value lower than 0 must result in clipping it to 0]
 # restart: --masking_functions.dictionaries_flush_interval_seconds=100
-SELECT @@global.masking_functions.dictionaries_flush_interval_seconds;
-@@global.masking_functions.dictionaries_flush_interval_seconds
-100
+include/assert.inc [dictionaries_flush_interval_seconds value after restart must be 100]
 CREATE USER udftest_priv@localhost;
 GRANT MASKING_DICTIONARIES_ADMIN ON *.* TO udftest_priv@localhost;
 SELECT masking_dictionary_term_add('single_dict_1', 'entry_1');
 masking_dictionary_term_add('single_dict_1', 'entry_1')
 1
-SELECT NAME FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%";
-NAME
-thread/masking_functions/masking_functions_dict_flusher
+include/assert.inc [after restart flusher thread must be running]
 REVOKE MASKING_DICTIONARIES_ADMIN ON *.* FROM udftest_priv@localhost;
 UNINSTALL COMPONENT 'file://component_masking_functions';
 REVOKE SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries FROM 'mysql.session'@'localhost';
 DROP USER udftest_priv@localhost;
 DROP TABLE mysql.masking_dictionaries;
-# restart:
+# restart

mysql-test/suite/component_masking_functions/t/flusher_thread_da_cleanup.test

@@ -0,0 +1,46 @@
+--source include/have_masking_functions_component.inc
+--source include/have_debug.inc
+--source include/have_debug_sync.inc
+
+--echo #
+--echo # PS-9611 "Assertion `!is_set() || m_can_overwrite_status' failure while server shutdown"
+--echo # https://perconadev.atlassian.net/browse/PS-9611
+--echo #
+
+CALL mtr.add_suppression("Flusher thread terminated while waiting for session server");
+CALL mtr.add_suppression("Exception during reloading dictionary cache");
+
+CREATE TABLE mysql.masking_dictionaries(
+    Dictionary VARCHAR(256) NOT NULL,
+    Term VARCHAR(256) NOT NULL,
+    UNIQUE INDEX dictionary_term_idx (Dictionary, Term)
+) ENGINE = InnoDB DEFAULT CHARSET=utf8mb4;
+
+GRANT SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries TO 'mysql.session'@'localhost';
+
+INSTALL COMPONENT 'file://component_masking_functions';
+
+--let $do_not_echo_parameters = 1
+--let $restart_parameters = restart: --debug=+d,enable_masking_functions_flush_thread_turbo_mode,enable_masking_functions_flush_thread_sync --masking_functions.dictionaries_flush_interval_seconds=31536000
+--source include/restart_mysqld.inc
+
+--let $assert_cond = LOCATE("enable_masking_functions_flush_thread_turbo_mode", @@global.debug) != 0
+--let $assert_text = Turbo mode must be enabled via DBUG
+--source include/assert.inc
+
+--let $assert_cond = @@global.masking_functions.dictionaries_flush_interval_seconds = 31536000
+--let $assert_text = dictionaries_flush_interval_seconds must be set to 1 year
+--source include/assert.inc
+
+SET debug_sync = 'now SIGNAL masking_functions_before_cache_reload_signal WAIT_FOR masking_functions_after_cache_reload_signal';
+
+SET debug_sync = 'RESET';
+
+--let $restart_parameters =
+--source include/shutdown_mysqld.inc
+--source include/start_mysqld.inc
+
+UNINSTALL COMPONENT 'file://component_masking_functions';
+
+REVOKE SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries FROM 'mysql.session'@'localhost';
+DROP TABLE mysql.masking_dictionaries;

mysql-test/suite/component_masking_functions/t/sys_var_dictionaries_flush_interval_seconds_basic.test

@@ -3,31 +3,50 @@
 CALL mtr.add_suppression("Flusher thread terminated while waiting for session server");
 CALL mtr.add_suppression("Flusher thread terminated after creating internal connection");
 CALL mtr.add_suppression("Server shutdown requested while attempting to establish flusher thread connection");
+CALL mtr.add_suppression("option 'masking-functions.dictionaries-flush-interval-seconds':.*adjusted");
 
 INSTALL COMPONENT 'file://component_masking_functions';
 
 # No running flusher thread with default settings
-SELECT @@global.masking_functions.dictionaries_flush_interval_seconds;
-SELECT NAME FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%";
+--let $assert_cond = @@global.masking_functions.dictionaries_flush_interval_seconds = 0
+--let $assert_text = default dictionaries_flush_interval_seconds value must be 0
+--source include/assert.inc
+
+--let $assert_cond = COUNT(*) FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%" = 0
+--let $assert_text = flusher thread must not be running
+--source include/assert.inc
 
 --error ER_INCORRECT_GLOBAL_LOCAL_VAR
-SET GLOBAL masking_functions.dictionaries_flush_interval_seconds=100;
+SET GLOBAL masking_functions.dictionaries_flush_interval_seconds = 100;
 
 --error ER_INCORRECT_GLOBAL_LOCAL_VAR
-SET SESSION masking_functions.dictionaries_flush_interval_seconds=100;
+SET SESSION masking_functions.dictionaries_flush_interval_seconds = 100;
 
 # Make sure dict flusher process is running
 CREATE TABLE mysql.masking_dictionaries(
     Dictionary VARCHAR(256) NOT NULL,
     Term VARCHAR(256) NOT NULL,
     UNIQUE INDEX dictionary_term_idx (Dictionary, Term)
-) ENGINE = InnoDB DEFAULT CHARSET=utf8mb4;
+) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
 GRANT SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries TO 'mysql.session'@'localhost';
 
---let $restart_parameters="restart: --masking_functions.dictionaries_flush_interval_seconds=100"
+--let $restart_parameters = restart: --masking_functions.dictionaries_flush_interval_seconds=31536001
+--source include/restart_mysqld.inc
+--let $assert_cond = @@global.masking_functions.dictionaries_flush_interval_seconds = 31536000
+--let $assert_text = setting dictionaries_flush_interval_seconds to a value higher than 31536000 must result in clipping it to 31536000
+--source include/assert.inc
+
+--let $restart_parameters = restart: --masking_functions.dictionaries_flush_interval_seconds=-1
 --source include/restart_mysqld.inc
+--let $assert_cond = @@global.masking_functions.dictionaries_flush_interval_seconds = 0
+--let $assert_text = setting dictionaries_flush_interval_seconds to a value lower than 0 must result in clipping it to 0
+--source include/assert.inc
 
-SELECT @@global.masking_functions.dictionaries_flush_interval_seconds;
+--let $restart_parameters = restart: --masking_functions.dictionaries_flush_interval_seconds=100
+--source include/restart_mysqld.inc
+--let $assert_cond = @@global.masking_functions.dictionaries_flush_interval_seconds = 100
+--let $assert_text = dictionaries_flush_interval_seconds value after restart must be 100
+--source include/assert.inc
 
 CREATE USER udftest_priv@localhost;
 GRANT MASKING_DICTIONARIES_ADMIN ON *.* TO udftest_priv@localhost;
@@ -37,7 +56,9 @@ SELECT masking_dictionary_term_add('single_dict_1', 'entry_1');
 
 # Flusher thread is active
 --connection default
-SELECT NAME FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%";
+--let $assert_cond = COUNT(*) FROM performance_schema.threads WHERE NAME LIKE "%masking_functions%" = 1
+--let $assert_text = after restart flusher thread must be running
+--source include/assert.inc
 
 #
 # Cleanup
@@ -51,5 +72,5 @@ REVOKE SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries FROM 'mysql.
 DROP USER udftest_priv@localhost;
 DROP TABLE mysql.masking_dictionaries;
 
---let $restart_parameters="restart:"
+--let $restart_parameters =
 --source include/restart_mysqld.inc