From 6fb7b579055e1416e7e334288ad1c5eb7c43560c Mon Sep 17 00:00:00 2001 From: Yura Sorokin Date: Wed, 5 Feb 2025 03:32:42 +0100 Subject: [PATCH] PS-9611 fix: Assertion '!is_set() || m_can_overwrite_status' failure while server shutdown https://perconadev.atlassian.net/browse/PS-9611 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Changed max value of the 'masking_functions.dictionaries_flush_interval_seconds' variable: instead of 'ULLONG_MAX' we now limit it to 60 * 60 * 24 * 365 seconds = 31 536 000 seconds (1 year). Improved 'is_terminated_lambda' in the 'dictionary_flusher_thread' - we now also check for additional server termination conditions. Improved how 'dictionary_flusher_thread' reloads cache - before executing dictionary table SELECT, we now always reset diagnostic area in THD object to an empty state. Added new 'enable_masking_functions_flush_thread_turbo_mode' DBUG option which helps to simulate continuous (without delays) cache reload. Added new 'component_masking_functions.flusher_thread_da_cleanup' MTR test case which simulates the scenario reported in the bug description. Added new checks to the 'component_masking_functions.sys_var_dictionaries_flush_interval_seconds_basic' MTR test case - we now check for min and max values of the 'dictionaries_flush_interval_seconds' variable. --- .../masking_functions/server_helpers.hpp | 6 +++ .../dictionary_flusher_thread.cpp | 36 +++++++++++++-- .../src/masking_functions/server_helpers.cpp | 9 ++++ .../src/masking_functions/sys_vars.cpp | 9 +++- .../r/flusher_thread_da_cleanup.result | 22 +++++++++ ...naries_flush_interval_seconds_basic.result | 28 ++++++----- .../t/flusher_thread_da_cleanup.test | 46 +++++++++++++++++++ ...ionaries_flush_interval_seconds_basic.test | 39 ++++++++++++---- 8 files changed, 166 insertions(+), 29 deletions(-) create mode 100644 mysql-test/suite/component_masking_functions/r/flusher_thread_da_cleanup.result create mode 100644 mysql-test/suite/component_masking_functions/t/flusher_thread_da_cleanup.test diff --git a/components/masking_functions/include/masking_functions/server_helpers.hpp b/components/masking_functions/include/masking_functions/server_helpers.hpp index 40dfc0bf95a5..da5f669ca105 100644 --- a/components/masking_functions/include/masking_functions/server_helpers.hpp +++ b/components/masking_functions/include/masking_functions/server_helpers.hpp @@ -18,6 +18,8 @@ #include +class THD; + namespace masking_functions { using lock_protected_function = std::function; @@ -31,6 +33,10 @@ using lock_protected_function = std::function; // 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 diff --git a/components/masking_functions/src/masking_functions/dictionary_flusher_thread.cpp b/components/masking_functions/src/masking_functions/dictionary_flusher_thread.cpp index 93375464e5ed..4c7a97585e5b 100644 --- a/components/masking_functions/src/masking_functions/dictionary_flusher_thread.cpp +++ b/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); } diff --git a/components/masking_functions/src/masking_functions/server_helpers.cpp b/components/masking_functions/src/masking_functions/server_helpers.cpp index f5797104c1a3..396808f55088 100644 --- a/components/masking_functions/src/masking_functions/server_helpers.cpp +++ b/components/masking_functions/src/masking_functions/server_helpers.cpp @@ -18,6 +18,7 @@ #include #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 diff --git a/components/masking_functions/src/masking_functions/sys_vars.cpp b/components/masking_functions/src/masking_functions/sys_vars.cpp index 41ceac079bc7..3bb73cc6a8f0 100644 --- a/components/masking_functions/src/masking_functions/sys_vars.cpp +++ b/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, diff --git a/mysql-test/suite/component_masking_functions/r/flusher_thread_da_cleanup.result b/mysql-test/suite/component_masking_functions/r/flusher_thread_da_cleanup.result new file mode 100644 index 000000000000..78bb0d78870e --- /dev/null +++ b/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: +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: +UNINSTALL COMPONENT 'file://component_masking_functions'; +REVOKE SELECT, INSERT, UPDATE, DELETE ON mysql.masking_dictionaries FROM 'mysql.session'@'localhost'; +DROP TABLE mysql.masking_dictionaries; diff --git a/mysql-test/suite/component_masking_functions/r/sys_var_dictionaries_flush_interval_seconds_basic.result b/mysql-test/suite/component_masking_functions/r/sys_var_dictionaries_flush_interval_seconds_basic.result index 8e78bd0b0b77..3d1202d0beaf 100644 --- a/mysql-test/suite/component_masking_functions/r/sys_var_dictionaries_flush_interval_seconds_basic.result +++ b/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 diff --git a/mysql-test/suite/component_masking_functions/t/flusher_thread_da_cleanup.test b/mysql-test/suite/component_masking_functions/t/flusher_thread_da_cleanup.test new file mode 100644 index 000000000000..444ac7fa33c0 --- /dev/null +++ b/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; diff --git a/mysql-test/suite/component_masking_functions/t/sys_var_dictionaries_flush_interval_seconds_basic.test b/mysql-test/suite/component_masking_functions/t/sys_var_dictionaries_flush_interval_seconds_basic.test index 7a260a4c4549..dd778a3f75d2 100644 --- a/mysql-test/suite/component_masking_functions/t/sys_var_dictionaries_flush_interval_seconds_basic.test +++ b/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