Semisync histogram double free

[laurynas-biveinis]

Avoid double free on latency histogram data

Before this fix, rpl.rpl_semi_sync_alias test under ASan with

=================================================================
==65389==ERROR: AddressSanitizer: heap-use-after-free on address 0x0001742e17d4 at pc 0x000107febaf0 bp 0x00016ea8f710 sp 0x00016ea8f708
READ of size 4 at 0x0001742e17d4 thread T80
    #0 0x107febaec in my_free(void*) my_malloc.cc:135
    #1 0x103cb9828 in free_latency_histogram_sysvars(SHOW_VAR*) mysqld.cc:4668
    #2 0x103cb99bc in prepare_latency_histogram_vars(latency_histogram*, SHOW_VAR*, unsigned long long*) mysqld.cc:4692
    #3 0x17c65826c in rpl_semi_sync_master_trx_wait_histogram(THD*, SHOW_VAR*, char*) semisync_source_plugin.cc:581
    #4 0x10be1b4cc in PFS_status_variable_cache::manifest(THD*, SHOW_VAR const*, System_status_var*, char const*, bool, bool) pfs_variable.cc:1366
    #5 0x10be1ba90 in PFS_status_variable_cache::do_materialize_all(THD*) pfs_variable.cc:1172
    #6 0x10c0ab33c in PFS_variable_cache<Status_variable>::materialize_all(THD*) pfs_variable.h:536
    #7 0x10c0ab294 in table_session_status::rnd_init(bool) table_session_status.cc:111
    #8 0x10bceb790 in ha_perfschema::rnd_init(bool) ha_perfschema.cc:1686
    #9 0x1033c7cec in handler::ha_rnd_init(bool) handler.cc:3157
    #10 0x103975380 in TableScanIterator::Init() basic_row_iterators.cc:230
    #11 0x103a33a18 in FilterIterator::Init() composite_iterators.h:82
    #12 0x103982ec0 in MaterializeIterator::MaterializeQueryBlock(MaterializeIterator::QueryBlock const&, unsigned long long*) composite_iterators.cc:845
    #13 0x103981410 in MaterializeIterator::Init() composite_iterators.cc:660
    #14 0x1049fc518 in Query_expression::ExecuteIteratorQuery(THD*) sql_union.cc:1293
    #15 0x1049fd358 in Query_expression::execute(THD*) sql_union.cc:1355
    #16 0x1047ae7ac in Sql_cmd_dml::execute_inner(THD*) sql_select.cc:870
    #17 0x1047ac344 in Sql_cmd_dml::execute(THD*) sql_select.cc:618
    #18 0x1047ffcc8 in Sql_cmd_show::execute(THD*) sql_show.cc:232
    #19 0x10480ab58 in Sql_cmd_show_status::execute(THD*) sql_show.cc:894
    #20 0x1045cea6c in mysql_execute_command(THD*, bool, unsigned long long*) sql_parse.cc:5323
    #21 0x1045c5dcc in dispatch_sql_command(THD*, Parser_state*, unsigned long long*) sql_parse.cc:6093
    #22 0x1045bb92c in dispatch_command(THD*, COM_DATA const*, enum_server_command) sql_parse.cc:2444
    #23 0x1045c06f8 in do_command(THD*) sql_parse.cc:1636
    #24 0x104cc4cc4 in handle_connection(void*) connection_handler_per_thread.cc:307
    #25 0x10bd130d4 in pfs_spawn_thread(void*) pfs.cc:2983
    #26 0x18ad47fa4 in _pthread_start+0x90 (libsystem_pthread.dylib:arm64e+0x6fa4)
    #27 0x18ad42d9c in thread_start+0x4 (libsystem_pthread.dylib:arm64e+0x1d9c)

0x0001742e17d4 is located 4 bytes inside of 40-byte region [0x0001742e17d0,0x0001742e17f8)
freed by thread T80 here:
    #0 0x139ff6de4 in wrap_free+0x98 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x3ede4)
    #1 0x107febcfc in my_raw_free(void*) my_malloc.cc:269
    #2 0x107feba48 in my_free(void*) my_malloc.cc:141
    #3 0x103cb9828 in free_latency_histogram_sysvars(SHOW_VAR*) mysqld.cc:4668
    #4 0x17c6231e8 in ReplSemiSyncMaster::~ReplSemiSyncMaster() semisync_source.cc:517
    #5 0x17c623488 in ReplSemiSyncMaster::~ReplSemiSyncMaster() semisync_source.cc:516
    #6 0x17c651484 in semi_sync_master_plugin_deinit(void*) semisync_source_plugin.cc:833
    #7 0x10467aa90 in plugin_deinitialize(st_plugin_int*, bool) sql_plugin.cc:1123
    #8 0x1046730b0 in reap_plugins() sql_plugin.cc:1192
    #9 0x1046863b4 in mysql_uninstall_plugin(THD*, MYSQL_LEX_CSTRING) sql_plugin.cc:2602
    #10 0x104685374 in Sql_cmd_uninstall_plugin::execute(THD*) sql_plugin.cc:3731
    #11 0x1045cea6c in mysql_execute_command(THD*, bool, unsigned long long*) sql_parse.cc:5323
    #12 0x1045c5dcc in dispatch_sql_command(THD*, Parser_state*, unsigned long long*) sql_parse.cc:6093
    #13 0x1045bb92c in dispatch_command(THD*, COM_DATA const*, enum_server_command) sql_parse.cc:2444
    #14 0x1045c06f8 in do_command(THD*) sql_parse.cc:1636
    #15 0x104cc4cc4 in handle_connection(void*) connection_handler_per_thread.cc:307
    #16 0x10bd130d4 in pfs_spawn_thread(void*) pfs.cc:2983
    #17 0x18ad47fa4 in _pthread_start+0x90 (libsystem_pthread.dylib:arm64e+0x6fa4)
    #18 0x18ad42d9c in thread_start+0x4 (libsystem_pthread.dylib:arm64e+0x1d9c)

It seems that the double invocation of free_latency_histogram_sysvars is
correct in this case, thus protect against the double free with resetting the
pointers to nullptr.

Squash with 19345e3

[laurynas-biveinis]

Other tests that show the same issue: rpl_nogtid.rpl_semi_sync_sender_observe_commit_only, rpl_nogtid.rpl_semi_sync, rpl_nogtid.rpl_semi_sync_optimize_for_static_plugin_config, rpl_nogtid.rpl_ssl_semisync, rpl_nogtid.rpl_semi_sync_uninstall_plugin

[hermanlee]

While the fix might resolve the double free, it seems like it opens up the possibility of lost memory. Based on the stack traces, the semi-sync plugin is being de-initialized/de-allocated and freeing up its internal memory. However, later in the same thread, there is a call to pfs to fetch data from a plugin that is being deallocated, so memory is reallocated for the histograms. It's not clear when this allocated memory is freed because de-initialization has already been called.

It seems like this is an upstream bug where the system_vars should be removed/disabled when the status_vars are being disabled in plugin_deinitialize(). Instead, system_vars are removed in plugin_del(). Would the right fix be to move the code around system_vars remove from plugin_del() to plugin_deinitialize()?

[hermanlee]

Maybe the following diff?

diff --git a/sql/sql_plugin.cc b/sql/sql_plugin.cc
index 9aee2367d64..8dd4c0728b7 100644
--- a/sql/sql_plugin.cc
+++ b/sql/sql_plugin.cc
@@ -1113,6 +1113,10 @@ static void plugin_deinitialize(st_plugin_int *plugin, bool ref_check) {
     remove_status_vars(plugin->plugin->status_vars);
   }
 
+  mysql_rwlock_wrlock(&LOCK_system_variables_hash);
+  mysql_del_sys_var_chain(plugin->system_vars);
+  mysql_rwlock_unlock(&LOCK_system_variables_hash);
+
   if (plugin_type_deinitialize[plugin->plugin->type]) {
     if ((*plugin_type_deinitialize[plugin->plugin->type])(plugin)) {
       LogErr(ERROR_LEVEL, ER_PLUGIN_FAILED_DEINITIALIZATION, plugin->name.str,

[laurynas-biveinis]

While the fix might resolve the double free, it seems like it opens up the possibility of lost memory. Based on the stack traces, the semi-sync plugin is being de-initialized/de-allocated and freeing up its internal memory. However, later in the same thread, there is a call to pfs to fetch data from a plugin that is being deallocated, so memory is reallocated for the histograms. It's not clear when this allocated memory is freed because de-initialization has already been called.

@hermanlee , could you please point to the source location for "later in the same thread, there is a call to pfs to fetch data from a plugin that is being deallocated, so memory is reallocated for the histograms"?

[hermanlee]

This is based on the stack trace provided.

plugin_deinitialize() -> semi_sync_master_plugin_deinit() -> ReplSemiSyncMaster::~ReplSemiSyncMaster() -> free_latency_histogram_sysvars() is where the memory is freed.

The double free original crash occurred in ha_perfschema::rnd_init() -> PFS_status_variable_cache::manifest() -> prepare_latency_histogram_vars() because free_latency_histogram_sysvar() was called during plugin_deinitalize() and the pointer was kept around. Your fix changes the pointer to nulltpr during the free, so that prepare_latency_histogram_vars() no longer crashes on the double free. However, semi_sync_master_plugin_deinit() has already been called, and nothing outside the plugin calls into free_latency_histogram_sysvar() again. Once the perfschema run completes, reap_plugins() then completes and the memory allocated by perf_schema in prepare_latency_histogram_vars() never gets freed.

[hermanlee]

This is based on the stack trace provided.

plugin_deinitialize() -> semi_sync_master_plugin_deinit() -> ReplSemiSyncMaster::~ReplSemiSyncMaster() -> free_latency_histogram_sysvars() is where the memory is freed.

The double free original crash occurred in ha_perfschema::rnd_init() -> PFS_status_variable_cache::manifest() -> prepare_latency_histogram_vars() because free_latency_histogram_sysvar() was called during plugin_deinitalize() and the pointer was kept around. Your fix changes the pointer to nulltpr during the free, so that prepare_latency_histogram_vars() no longer crashes on the double free. However, semi_sync_master_plugin_deinit() has already been called, and nothing outside the plugin calls into free_latency_histogram_sysvar() again. Once the perfschema run completes, reap_plugins() then completes and the memory allocated by perf_schema in prepare_latency_histogram_vars() never gets freed.

[laurynas-biveinis]

@hermanlee, I have reviewed as much as I was able to, and to the best of my understanding your proposed patch is correct. I'd check the whole testsuite under ASan or Valgrind for the unknown unknowns, and then report upstream and try to upstream the patch or at least get their opinion.

Since this is your patch, do you want to work on this or do you want me to take it?

[hermanlee]

Does the patch resolve the ASAN issues you saw? I can file a bug report for this upstream, but generating a test case might be more difficult. Did you discover how the performance schema call was being made on the plugin after it was de-initialized while running on the same thread?

[laurynas-biveinis]

I made an error in my testing. The proposed patch does not fix the issue, and the sequence of actions is different than assumed. The following three things happen:

1. The plugin is uninstalled, freeing the histograms the first time. Note that this step can be considered atomic, i.e. it does not matter if it's free'ed at deinitialization or unload.
2. The plugin is re-installed again.
3. A status variable query happens, freeing the histograms the second time.

I am analyzing this further. I guess we need to re-check whether my original patch results in a memory leak, as in the above scenario there will be one more plugin unload.

[laurynas-biveinis]

I am still not sure what's going on. The crash/ASan error reproduces on macOS, but not on Linux. I cannot tell yet whether Linux is lucky with the bug being present there but not tripping, or whether there is no bug on Linux in the first place. The previous comment describes what is happening on macOS. On Linux, there is no 2nd free.

[laurynas-biveinis]

I got to the bottom of it and the PR is ready for review. Repeated installation, use, and uninstallation of a plugin results in platform-specific behavior with respect to uninitialized variables in the BSS section. For ELF, they are zero-initialized on every load. For mach-O, apparently they were on the first load, but not later (maybe the unload is postponed?).

It is possible to reproduce the issue on Linux by adding RTLD_NODELETE flag to dlopen call in plugin_dl_add, which is documented as "Do not unload the shared object during dlclose(). Consequently, the object's static and global variables are not reinitialized if the object is reloaded with dlopen() at a later time.", and then the fix works too.

POSIX docs for dlopen do not say anything about BSS and repeated loading.

[facebook-github-bot]

@hermanlee has imported this pull request. If you are a Meta employee, you can view this diff on Phabricator.

[hermanlee]

Awesome, thanks for tracking this down.