Merge pull request #731 from KernelMaker/more_logging_in_ndbcluster_init-22.10

mronstro · web-flow · commit 8ffc642da6f6 · 2025-06-30T12:25:42.000+02:00
BACKPORT: Add more logging to ndbcluster_init() to improve observabil…
diff --git a/storage/ndb/plugin/ha_ndb_index_stat.cc b/storage/ndb/plugin/ha_ndb_index_stat.cc
@@ -2194,6 +2194,7 @@ void Ndb_index_stat_thread::do_run() {
     Wait for cluster to start
   */
   while (!ndb_connection_is_ready(g_ndb_cluster_connection, 1)) {
+    log_info("Retrying: checking ndb_connection_is_ready");
     /* NDB not connected yet */
     if (is_stop_requested()) {
       /* Terminated with a stop_request */
@@ -2287,13 +2288,24 @@ void Ndb_index_stat_thread::do_run() {
 
       // the Ndb object is needed first
       if (pr.ndb == nullptr) {
-        if (create_ndb(&pr, g_ndb_cluster_connection) == -1) break;
+        if (create_ndb(&pr, g_ndb_cluster_connection) == -1) {
+          log_info("Retrying: create_ndb failed");
+          break;
+        }
       }
 
       // sys objects
       if (check_sys) {
         // at enable check or create stats tables and events
-        if (check_systables(pr) == -1 || check_sysevents(pr) == -1) break;
+        int check_table_ret = 0;
+        int check_event_ret = 0;
+        if ((check_table_ret = check_systables(pr)) == -1 ||
+            (check_event_ret = check_sysevents(pr)) == -1) {
+          log_info("Retrying: checking both check_systable and check_sysevent, "
+                   "last check result: [%d, %d]",
+                    check_table_ret, check_event_ret);
+          break;
+        }
       }
 
       // listener is not critical but error means something is wrong
diff --git a/storage/ndb/plugin/ha_ndbcluster.cc b/storage/ndb/plugin/ha_ndbcluster.cc
@@ -12232,7 +12232,7 @@ extern THD *ndb_create_thd(char *stackptr);
 // Functionality used for delaying MySQL Server startup until
 // connection to NDB and setup (of index stat plus binlog) has completed
 //
-static bool wait_setup_completed(ulong max_wait_seconds) {
+static bool wait_setup_completed(ulong max_wait_seconds, const std::string info_tag) {
   DBUG_TRACE;
 
   const auto timeout_time =
@@ -12241,8 +12241,15 @@ static bool wait_setup_completed(ulong max_wait_seconds) {
   while (std::chrono::steady_clock::now() < timeout_time) {
     if (ndb_binlog_is_initialized() &&
         ndb_index_stat_thread.is_setup_complete()) {
+      ndb_log_info("[TRACE][%s][wait_setup_completed] Done!",
+                   info_tag.c_str());
       return true;
     }
+    ndb_log_info("[TRACE][%s][wait_setup_completed], "
+                 "ndb_binlog_is_ready: %u ndb_index_stat_allow_flag: %u",
+                 info_tag.c_str(),
+                 ndb_binlog_is_initialized(),
+                 ndb_index_stat_thread.is_setup_complete());
     ndb_milli_sleep(100);
   }
 
@@ -12266,7 +12273,7 @@ static int ndb_wait_setup_server_startup(void *) {
   ndb_metadata_change_monitor_thread.set_server_started();
 
   // Wait for connection to NDB and thread(s) setup
-  if (wait_setup_completed(opt_ndb_wait_setup) == false) {
+  if (wait_setup_completed(opt_ndb_wait_setup, "main") == false) {
     ndb_log_error(
         "Tables not available after %lu seconds. Consider "
         "increasing --ndb-wait-setup value",
@@ -12535,6 +12542,7 @@ static int ndbcluster_init(void *handlerton_ptr) {
     return 0;  // Return before init will disable ndbcluster-SE.
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][13 steps expected for successful completion]");
   /* Check const alignment */
   static_assert(DependencyTracker::InvalidTransactionId ==
                 Ndb_binlog_extra_row_info::InvalidTransactionId);
@@ -12549,7 +12557,7 @@ static int ndbcluster_init(void *handlerton_ptr) {
   }
 
   std::function<bool()> start_channel_func = []() -> bool {
-    if (!wait_setup_completed(opt_ndb_wait_setup)) {
+    if (!wait_setup_completed(opt_ndb_wait_setup, "channel")) {
       ndb_log_error(
           "Replica: Connection to NDB not ready after %lu seconds. "
           "Consider increasing --ndb-wait-setup value",
@@ -12559,15 +12567,18 @@ static int ndbcluster_init(void *handlerton_ptr) {
     return true;
   };
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][1] Calling Ndb_replica::init");
   if (Ndb_replica::init(start_channel_func, &g_default_channel_stats)) {
     return ndbcluster_init_abort("Failed to initialize NDB Replica");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][2] Calling Ndb_index_stat_thread::init");
   if (ndb_index_stat_thread.init() ||
       DBUG_EVALUATE_IF("ndbcluster_init_fail1", true, false)) {
     return ndbcluster_init_abort("Failed to initialize NDB Index Stat");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][3] Calling Ndb_metadata_change_monitor::init");
   if (ndb_metadata_change_monitor_thread.init()) {
     return ndbcluster_init_abort(
         "Failed to initialize NDB Metadata Change Monitor");
@@ -12591,6 +12602,7 @@ static int ndbcluster_init(void *handlerton_ptr) {
   hton->get_tablespace_statistics =
       ndbcluster_get_tablespace_statistics;           /* Provide data to I_S */
   hton->partition_flags = ndbcluster_partition_flags; /* Partition flags */
+  ndb_log_info("[TRACE][main][ndbcluster_init][4] Calling ndbcluster_binlog_init");
   if (!ndbcluster_binlog_init(hton))
     return ndbcluster_init_abort("Failed to initialize NDB Binlog");
   hton->flags = HTON_TEMPORARY_NOT_SUPPORTED | HTON_NO_BINLOG_ROW_OPT |
@@ -12620,20 +12632,24 @@ static int ndbcluster_init(void *handlerton_ptr) {
   // SO, that GSL will not be held unnecessary for non-NDB tables.
   hton->post_ddl = ndbcluster_post_ddl;
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][5] Calling ndb_init_internal");
   // Initialize NdbApi
   ndb_init_internal(1);
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][6] Calling Ndb_server_hooks::register_server_hooks");
   if (!ndb_server_hooks.register_server_hooks(ndb_wait_setup_server_startup,
                                               ndb_dd_upgrade_hook)) {
     return ndbcluster_init_abort("Failed to register server start hook");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][7] Calling NDB_SHARE::initialize");
   // Initialize NDB_SHARE factory
   NDB_SHARE::initialize(table_alias_charset);
 
   /* allocate connection resources and connect to cluster */
   const uint global_opti_node_select =
       THDVAR(nullptr, optimized_node_selection);
+  ndb_log_info("[TRACE][main][ndbcluster_init][8] Calling ndbcluster_connect");
   if (ndbcluster_connect(
           opt_ndb_wait_connected, opt_ndb_cluster_connection_pool,
           opt_connection_pool_nodeids_str, (global_opti_node_select & 1),
@@ -12653,22 +12669,26 @@ static int ndbcluster_init(void *handlerton_ptr) {
     }
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][9] Calling ndbcluster_binlog_start");
   /* start the ndb injector thread */
   if (ndbcluster_binlog_start()) {
     return ndbcluster_init_abort("Failed to start NDB Binlog");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][10] Calling Ndb_index_stat_thread::start");
   // Create index statistics thread
   if (ndb_index_stat_thread.start() ||
       DBUG_EVALUATE_IF("ndbcluster_init_fail2", true, false)) {
     return ndbcluster_init_abort("Failed to start NDB Index Stat");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][11] Calling Ndb_metadata_change_monitor::start");
   // Create metadata change monitor thread
   if (ndb_metadata_change_monitor_thread.start()) {
     return ndbcluster_init_abort("Failed to start NDB Metadata Change Monitor");
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][12] Calling ndb_pfs_init");
   if (ndb_pfs_init()) {
     return ndbcluster_init_abort("Failed to init pfs");
   }
@@ -12694,6 +12714,7 @@ static int ndbcluster_init(void *handlerton_ptr) {
     opt_ndb_slave_conflict_role = opt_ndb_applier_conflict_role;
   }
 
+  ndb_log_info("[TRACE][main][ndbcluster_init][13] Done!");
   ndbcluster_inited = 1;
 
   return 0;  // OK
diff --git a/storage/ndb/plugin/ha_ndbcluster_binlog.cc b/storage/ndb/plugin/ha_ndbcluster_binlog.cc
@@ -816,6 +816,8 @@ class Ndb_binlog_setup {
       ndb_log_info(" <- sleep");
     }
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][11 steps expected for successful completion]");
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][1] Calling Ndb_global_schema_lock_guard");
     // Protect the schema synchronization with GSL(Global Schema Lock)
     Ndb_global_schema_lock_guard global_schema_lock_guard(m_thd);
     if (global_schema_lock_guard.lock()) {
@@ -831,6 +833,7 @@ class Ndb_binlog_setup {
       }
     });
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][2] Calling Ndb_binlog_setup::detect_initial_restart");
     // Check if this is a initial restart/start
     bool initial_system_restart = false;
     if (!detect_initial_restart(thd_ndb, &initial_system_restart)) {
@@ -851,11 +854,13 @@ class Ndb_binlog_setup {
 
     Ndb_dd_sync dd_sync(m_thd, thd_ndb);
     if (initial_system_restart) {
+      ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][3] Calling Ndb_dd_sync::remove_all_metadata");
       // Remove all NDB metadata from DD since this is an initial restart
       if (!dd_sync.remove_all_metadata()) {
         return false;
       }
     } else {
+      ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][3] Calling Ndb_dd_sync::remove_deleted_tables");
       /*
         Not an initial restart. Delete DD table definitions corresponding to NDB
         tables that no longer exist in NDB Dictionary. This is to ensure that
@@ -872,6 +877,7 @@ class Ndb_binlog_setup {
     thd_ndb_options.set(Thd_ndb::ALLOW_BINLOG_SETUP);
 
     const bool ndb_schema_dist_upgrade_allowed = ndb_allow_ndb_schema_upgrade();
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][4] Calling Ndb_schema_dist_table::create_or_upgrade");
     Ndb_schema_dist_table schema_dist_table(thd_ndb);
     if (!schema_dist_table.create_or_upgrade(m_thd,
                                              ndb_schema_dist_upgrade_allowed))
@@ -901,6 +907,7 @@ class Ndb_binlog_setup {
       assert(false);
     }
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][5] Calling Ndb_schema_result_table::create_or_upgrade");
     Ndb_schema_result_table schema_result_table(thd_ndb);
     if (!schema_result_table.create_or_upgrade(m_thd,
                                                ndb_schema_dist_upgrade_allowed))
@@ -916,9 +923,11 @@ class Ndb_binlog_setup {
       return false;
     }
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][6] Calling Ndb_index_stat_head_table::create_or_upgrade");
     Ndb_index_stat_head_table index_stat_head_table(thd_ndb);
     if (!index_stat_head_table.create_or_upgrade(m_thd, true)) return false;
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][7] Calling Ndb_index_stat_sample_table::create_or_upgrade");
     Ndb_index_stat_sample_table index_stat_sample_table(thd_ndb);
     if (!index_stat_sample_table.create_or_upgrade(m_thd, true)) return false;
 
@@ -929,14 +938,17 @@ class Ndb_binlog_setup {
       ndb_index_stat_restart();
     }
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][8] Calling Ndb_apply_status_table::create_or_upgrade");
     Ndb_apply_status_table apply_status_table(thd_ndb);
     if (!apply_status_table.create_or_upgrade(m_thd, true)) return false;
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][9] Calling Ndb_dd_sync::synchronize");
     if (!dd_sync.synchronize()) {
       ndb_log_verbose(9, "Failed to synchronize DD with NDB");
       return false;
     }
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][10] Calling Ndb_dd_sync::Ndb_stored_grants::setup");
     if (!Ndb_stored_grants::setup(m_thd, thd_ndb)) {
       ndb_log_warning("Failed to setup synchronized privileges");
       return false;
@@ -949,6 +961,7 @@ class Ndb_binlog_setup {
     // nodes run a version that has support for the Data Dictionary.
     Ndb_schema_dist_client::block_ddl(!ndb_all_nodes_support_mysql_dd());
 
+    ndb_log_info("[TRACE][binlog][Ndb_binlog_setup][11] Done!");
     return true;  // Setup completed OK
   }
 };
@@ -7407,8 +7420,13 @@ void Ndb_binlog_thread::do_run() {
 
     assert(m_apply_status_share == nullptr);
 
-    while (!ndb_connection_is_ready(thd_ndb->connection, 1) ||
-           !binlog_setup.setup(thd_ndb)) {
+    bool ret_conn_is_ready = false;
+    bool ret_binlog_setup = false;
+    while (!(ret_conn_is_ready = ndb_connection_is_ready(thd_ndb->connection, 1)) ||
+           !(ret_binlog_setup = binlog_setup.setup(thd_ndb))) {
+      log_info("Retrying: checking both ndb_connection_is_ready "
+               "and Ndb_binlog_setup::setup, last check result: [%d, %d]",
+               ret_conn_is_ready, ret_binlog_setup);
       // Failed to complete binlog_setup, remove all existing event
       // operations from potential partial setup
       remove_all_event_operations(s_ndb, i_ndb);
diff --git a/storage/ndb/plugin/ndb_metadata_change_monitor.cc b/storage/ndb/plugin/ndb_metadata_change_monitor.cc
@@ -509,6 +509,7 @@ void Ndb_metadata_change_monitor::do_run() {
     // Outer loop to ensure that if the connection to NDB is lost, a fresh
     // connection is established before the thread continues its processing
     while (!ndb_connection_is_ready(thd_ndb->connection, 1)) {
+      log_info("Retrying: checking ndb_connection_is_ready");
       // No connection to NDB yet. Retry until connection is established while
       // checking if stop has been requested at 1 second intervals
       if (is_stop_requested()) {
diff --git a/storage/ndb/plugin/ndb_stored_grants.cc b/storage/ndb/plugin/ndb_stored_grants.cc
@@ -996,23 +996,28 @@ bool Ndb_stored_grants::setup(THD *thd, Thd_ndb *thd_ndb) {
     ndb_log_info("Ndb_stored_grants::setup() -- normal setup");
   }
 
+  ndb_log_info("[TRACE][binlog][Ndb_stored_grants::setup][4 steps expected for successful completion]");
   /* Create or upgrade the ndb_sql_metadata table.
      If this fails, create_or_upgrade() will log an error message,
      and we return false, which will cause the whole binlog setup
      routine to be retried.
   */
   Ndb_sql_metadata_table sql_metadata_table(thd_ndb);
+  ndb_log_info("[TRACE][binlog][Ndb_stored_grants::setup][1] Calling Ndb_sql_metadata_table::create_or_upgrade");
   if (!sql_metadata_table.create_or_upgrade(thd, true)) return false;
 
+  ndb_log_info("[TRACE][binlog][Ndb_stored_grants::setup][2] Calling Ndb_sql_metadata_table::setup");
   metadata_table.setup(thd_ndb->ndb->getDictionary(),
                        sql_metadata_table.get_table());
+  ndb_log_info("[TRACE][binlog][Ndb_stored_grants::setup][3] Calling Ndb_sql_metadata_table::initializeSnapshotLock");
   const NdbError &err = metadata_table.initializeSnapshotLock(thd_ndb->ndb);
   if (err.status != NdbError::Success) {
     ndb_log_error("ndb_stored_grants initalizeSnapshotLock failure: %d %s",
                   err.code, err.message);
     return false;
   }
 
+  ndb_log_info("[TRACE][binlog][Ndb_stored_grants::setup][4] Done!");
   return true;
 }
 
