Bug#31236217 : NOT HANDLING ERROR RETURNED FROM DDL_LOG_TABLE::INSERT MIGHT

               BREAK ATOMIC DDL

Issue:
  If there is an error while inserting log in ddl_log table, then returned
  error was lost and not returned. So impression is that ddl_log is inserted
  but it actually is not.

Fix:
  Handle returned error in above scenario and return error to run the DDL.
  Fixed issue where trx wasn't registered while doing tablespace encryption

RB : 24387
reviewed by : Kevin Lewis <[email protected]>

Author: mayprasa

mysql-test/suite/innodb/r/ddl_log_error.result

@@ -0,0 +1,23 @@
+# Setup
+CREATE TABLE t1 (c1 INT);
+CREATE TABLESPACE my_ts ADD DATAFILE "my_ts.ibd";
+SET SESSION DEBUG="+d,ddl_log_return_error_from_insert";
+# Run few DDLs. All DDLs should give error now.
+ALTER TABLE t1 RENAME to t2;
+ERROR HY000: Error on rename of './test/t1' to './test/t2' (errno: 168 - Unknown (generic) error from engine)
+ALTER TABLE t1 ADD COLUMN c2 INT, ALGORITHM=COPY;
+ERROR HY000: Got error 168 - 'Unknown (generic) error from engine' from storage engine
+ALTER TABLE t1 ADD COLUMN c2 INT, ALGORITHM=INPLACE;
+ERROR HY000: Got error 11 - 'InnoDB error' from storage engine
+DROP TABLE t1;
+ERROR HY000: Storage engine can't drop table 'test.t1'
+SET SESSION DEBUG="-d,ddl_log_return_error_from_insert";
+# Restart with keyring plugin
+SET SESSION DEBUG="+d,ddl_log_return_error_from_insert";
+ALTER TABLESPACE my_ts ENCRYPTION='Y';
+ERROR HY000: Failed to alter: TABLESPACE my_ts
+SET SESSION DEBUG="-d,ddl_log_return_error_from_insert";
+# Cleanup
+DROP TABLE t1;
+# Restarting server without keyring to restore server state
+# restart: 

mysql-test/suite/innodb/r/sdi_fail.result

@@ -12,6 +12,6 @@ t1	CREATE TABLE `t1` (
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
 SET DEBUG='+d,ib_create_table_fail_too_many_trx';
 ALTER TABLE t1 ADD INDEX (c2), ADD INDEX (c3);
-ERROR HY000: Failed to delete SDI 'test.t1' in tablespace 'test/t1'.
+ERROR HY000: Too many active concurrent transactions
 SET DEBUG='-d,ib_create_table_fail_too_many_trx';
 drop table t1;

mysql-test/suite/innodb/t/ddl_log_error.test

@@ -0,0 +1,55 @@
+#
+# BUG#31236217 : NOT HANDLING ERROR RETURNED FROM DDL_LOG_TABLE::INSERT MIGHT
+#                BREAK ATOMIC DDL
+#
+
+--source include/have_debug.inc
+
+--disable_query_log
+call mtr.add_suppression("\\[Error\\] \\[[^]]*\\] \\[[^]]*\\] Couldn't insert entry in ddl log for ddl.");
+call mtr.add_suppression("\\[Error\\] \\[[^]]*\\] \\[[^]]*\\] Couldn't write DDL LOG for");
+--enable_query_log
+
+--echo # Setup
+CREATE TABLE t1 (c1 INT);
+CREATE TABLESPACE my_ts ADD DATAFILE "my_ts.ibd";
+
+# Return error from insert into ddl_log
+SET SESSION DEBUG="+d,ddl_log_return_error_from_insert";
+
+--echo # Run few DDLs. All DDLs should give error now.
+
+--error ER_ERROR_ON_RENAME
+ALTER TABLE t1 RENAME to t2;
+
+--error ER_GET_ERRNO
+ALTER TABLE t1 ADD COLUMN c2 INT, ALGORITHM=COPY;
+
+--error ER_GET_ERRNO
+ALTER TABLE t1 ADD COLUMN c2 INT, ALGORITHM=INPLACE;
+
+--error ER_ENGINE_CANT_DROP_TABLE
+DROP TABLE t1;
+
+SET SESSION DEBUG="-d,ddl_log_return_error_from_insert";
+
+
+--echo # Restart with keyring plugin
+let $restart_parameters = restart: --early-plugin-load=keyring_file=$KEYRING_PLUGIN --loose-keyring_file_data=$MYSQL_TMP_DIR/mysecret_keyring $KEYRING_PLUGIN_OPT;
+--source include/restart_mysqld_no_echo.inc
+
+# Return error from insert into ddl_log
+SET SESSION DEBUG="+d,ddl_log_return_error_from_insert";
+
+--error ER_ALTER_FILEGROUP_FAILED
+ALTER TABLESPACE my_ts ENCRYPTION='Y';
+
+SET SESSION DEBUG="-d,ddl_log_return_error_from_insert";
+
+--echo # Cleanup
+DROP TABLE t1;
+remove_file $MYSQL_TMP_DIR/mysecret_keyring;
+
+--echo # Restarting server without keyring to restore server state
+let $restart_parameters = restart: ;
+--source include/restart_mysqld.inc

mysql-test/suite/innodb/t/sdi_fail.test

@@ -7,14 +7,15 @@
 --disable_query_log
 call mtr.add_suppression("sdi_delete failed: tablespace_id:");
 call mtr.add_suppression("Cannot save table statistics for table");
+call mtr.add_suppression("\\[Error\\] \\[[^]]*\\] \\[[^]]*\\] Couldn't insert entry in ddl log for ddl.");
 --enable_query_log
 
 create table t1(c1 int primary key, c2 char(1), c3 int unsigned);
 show create table t1;
 
 SET DEBUG='+d,ib_create_table_fail_too_many_trx';
 
---error ER_SDI_OPERATION_FAILED,
+--error ER_TOO_MANY_CONCURRENT_TRXS
 ALTER TABLE t1 ADD INDEX (c2), ADD INDEX (c3);
 
 SET DEBUG='-d,ib_create_table_fail_too_many_trx';

share/messages_to_error_log.txt

@@ -10910,6 +10910,10 @@ ER_AUTHCACHE_DEFAULT_ROLES_IGNORED_EMPTY_NAME
 
 ER_AUTHCACHE_DEFAULT_ROLES_UNKNOWN_AUTHORIZATION_ID
   eng "Found an entry in the 'default_roles' table with unknown authorization ID '%s'; Skipped"
+
+ER_IB_ERR_DDL_LOG_INSERT_FAILURE
+  eng "Couldn't insert entry in ddl log for ddl."
+
 # DO NOT add server-to-client messages here;
 # they go in messages_to_clients.txt
 # in the same directory as this file.

storage/innobase/handler/ha_innodb.cc

@@ -15017,6 +15017,8 @@ static int innobase_alter_encrypt_tablespace(handlerton *hton, THD *thd,
 
   /* Get the transaction associated with the current thd */
   trx = check_trx_exists(thd);
+  innobase_register_trx(hton, thd, trx);
+
   trx_start_if_not_started(trx, true);
 
   /* Make an entry in DDL LOG for this tablespace. */

storage/innobase/log/log0ddl.cc

@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 2017, 2019, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2017, 2020, Oracle and/or its affiliates.
 
 Portions of this file contain modifications contributed and copyrighted by
 Google, Inc. Those modifications are gratefully acknowledged and are described
@@ -470,15 +470,32 @@ dberr_t DDL_Log_Table::insert(const DDL_Record &record) {
   create_tuple(record);
   entry = row_build_index_entry(m_tuple, nullptr, index, m_heap);
 
-  error = row_ins_clust_index_entry_low(flags, BTR_MODIFY_LEAF, index,
-                                        index->n_uniq, entry, m_thr, false);
+#ifdef UNIV_DEBUG
+  bool insert = true;
+  DBUG_EXECUTE_IF("ddl_log_return_error_from_insert", insert = false;);
+
+  if (insert) {
+#endif
+    error = row_ins_clust_index_entry_low(flags, BTR_MODIFY_LEAF, index,
+                                          index->n_uniq, entry, m_thr, false);
+#ifdef UNIV_DEBUG
+  } else {
+    error = DB_ERROR;
+  }
+#endif
 
   if (error == DB_FAIL) {
     error = row_ins_clust_index_entry_low(flags, BTR_MODIFY_TREE, index,
                                           index->n_uniq, entry, m_thr, false);
     ut_ad(error == DB_SUCCESS);
   }
 
+  if (error != DB_SUCCESS) {
+    ib::error(ER_IB_ERR_DDL_LOG_INSERT_FAILURE);
+    mem_heap_free(offsets_heap);
+    return error;
+  }
+
   index = index->next();
 
   entry = row_build_index_entry(m_tuple, nullptr, index, m_heap);
@@ -860,15 +877,19 @@ dberr_t Log_DDL::write_free_tree_log(trx_t *trx, const dict_index_t *index,
   if (is_drop_table) {
     /* Drop index case, if committed, will be redo only */
     err = insert_free_tree_log(trx, index, id, thread_id);
-    ut_ad(err == DB_SUCCESS);
+    if (err != DB_SUCCESS) {
+      return err;
+    }
 
     DBUG_INJECT_CRASH("ddl_log_crash_after_free_tree_log",
                       crash_after_free_tree_log_counter++);
   } else {
     /* This is the case of building index during create table
     scenario. The index will be dropped if ddl is rolled back */
     err = insert_free_tree_log(nullptr, index, id, thread_id);
-    ut_ad(err == DB_SUCCESS);
+    if (err != DB_SUCCESS) {
+      return err;
+    }
 
     DBUG_INJECT_CRASH("ddl_log_crash_after_free_tree_log",
                       crash_after_free_tree_log_counter++);
@@ -917,15 +938,14 @@ dberr_t Log_DDL::insert_free_tree_log(trx_t *trx, const dict_index_t *index,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   if (!has_dd_trx) {
     trx_commit_for_mysql(trx);
     trx_free_for_background(trx);
   }
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_647) << "DDL log insert : " << record;
   }
 
@@ -955,14 +975,18 @@ dberr_t Log_DDL::write_delete_space_log(trx_t *trx, const dict_table_t *table,
   if (is_drop) {
     err = insert_delete_space_log(trx, id, thread_id, space_id, file_path,
                                   dict_locked);
-    ut_ad(err == DB_SUCCESS);
+    if (err != DB_SUCCESS) {
+      return err;
+    }
 
     DBUG_INJECT_CRASH("ddl_log_crash_after_delete_space_log",
                       crash_after_delete_space_log_counter++);
   } else {
     err = insert_delete_space_log(nullptr, id, thread_id, space_id, file_path,
                                   dict_locked);
-    ut_ad(err == DB_SUCCESS);
+    if (err != DB_SUCCESS) {
+      return err;
+    }
 
     DBUG_INJECT_CRASH("ddl_log_crash_after_delete_space_log",
                       crash_after_delete_space_log_counter++);
@@ -1014,7 +1038,6 @@ dberr_t Log_DDL::insert_delete_space_log(trx_t *trx, uint64_t id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   if (dict_locked) {
@@ -1026,7 +1049,7 @@ dberr_t Log_DDL::insert_delete_space_log(trx_t *trx, uint64_t id,
     trx_free_for_background(trx);
   }
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_648) << "DDL log insert : " << record;
   }
 
@@ -1062,11 +1085,16 @@ dberr_t Log_DDL::write_rename_space_log(space_id_t space_id,
 
   dberr_t err = insert_rename_space_log(id, thread_id, space_id, old_file_path,
                                         new_file_path);
-  ut_ad(err == DB_SUCCESS);
+  if (err != DB_SUCCESS) {
+    return err;
+  }
 
   DBUG_INJECT_CRASH("ddl_log_crash_after_rename_space_log",
                     crash_after_rename_space_log_counter++);
 
+  DBUG_EXECUTE_IF("ddl_log_crash_after_rename_space_log_insert",
+                  DBUG_SUICIDE(););
+
   DBUG_EXECUTE_IF("DDL_Log_remove_inject_error_4",
                   srv_inject_too_many_concurrent_trxs = true;);
 
@@ -1105,15 +1133,14 @@ dberr_t Log_DDL::insert_rename_space_log(uint64_t id, ulint thread_id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   mutex_enter(&dict_sys->mutex);
 
   trx_commit_for_mysql(trx);
   trx_free_for_background(trx);
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_649) << "DDL log insert : " << record;
   }
 
@@ -1141,7 +1168,9 @@ dberr_t Log_DDL::write_alter_encrypt_space_log(space_id_t space_id) {
                     crash_before_alter_encrypt_space_log_counter++);
 
   dberr_t err = insert_alter_encrypt_space_log(id, thread_id, space_id);
-  ut_ad(err == DB_SUCCESS);
+  if (err != DB_SUCCESS) {
+    return err;
+  }
 
   DBUG_INJECT_CRASH("ddl_log_crash_after_alter_encrypt_space_log",
                     crash_after_alter_encrypt_space_log_counter++);
@@ -1168,15 +1197,14 @@ dberr_t Log_DDL::insert_alter_encrypt_space_log(uint64_t id, ulint thread_id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   mutex_enter(&dict_sys->mutex);
 
   trx_commit_for_mysql(trx);
   trx_free_for_background(trx);
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_1284) << "DDL log insert : " << record;
   }
 
@@ -1198,7 +1226,9 @@ dberr_t Log_DDL::write_drop_log(trx_t *trx, const table_id_t table_id) {
 
   dberr_t err;
   err = insert_drop_log(trx, id, thread_id, table_id);
-  ut_ad(err == DB_SUCCESS);
+  if (err != DB_SUCCESS) {
+    return err;
+  }
 
   DBUG_INJECT_CRASH("ddl_log_crash_after_drop_log",
                     crash_after_drop_log_counter++);
@@ -1225,12 +1255,11 @@ dberr_t Log_DDL::insert_drop_log(trx_t *trx, uint64_t id, ulint thread_id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   mutex_enter(&dict_sys->mutex);
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_650) << "DDL log insert : " << record;
   }
 
@@ -1253,7 +1282,9 @@ dberr_t Log_DDL::write_rename_table_log(dict_table_t *table,
 
   dberr_t err =
       insert_rename_table_log(id, thread_id, table->id, old_name, new_name);
-  ut_ad(err == DB_SUCCESS);
+  if (err != DB_SUCCESS) {
+    return err;
+  }
 
   DBUG_EXECUTE_IF("DDL_Log_remove_inject_error_5",
                   srv_inject_too_many_concurrent_trxs = true;);
@@ -1290,15 +1321,14 @@ dberr_t Log_DDL::insert_rename_table_log(uint64_t id, ulint thread_id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   mutex_enter(&dict_sys->mutex);
 
   trx_commit_for_mysql(trx);
   trx_free_for_background(trx);
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_651) << "DDL log insert : " << record;
   }
 
@@ -1319,7 +1349,9 @@ dberr_t Log_DDL::write_remove_cache_log(trx_t *trx, dict_table_t *table) {
 
   dberr_t err =
       insert_remove_cache_log(id, thread_id, table->id, table->name.m_name);
-  ut_ad(err == DB_SUCCESS);
+  if (err != DB_SUCCESS) {
+    return err;
+  }
 
   DBUG_EXECUTE_IF("DDL_Log_remove_inject_error_3",
                   srv_inject_too_many_concurrent_trxs = true;);
@@ -1351,13 +1383,12 @@ dberr_t Log_DDL::insert_remove_cache_log(uint64_t id, ulint thread_id,
   {
     DDL_Log_Table ddl_log(trx);
     error = ddl_log.insert(record);
-    ut_ad(error == DB_SUCCESS);
   }
 
   trx_commit_for_mysql(trx);
   trx_free_for_background(trx);
 
-  if (srv_print_ddl_logs) {
+  if (error == DB_SUCCESS && srv_print_ddl_logs) {
     ib::info(ER_IB_MSG_652) << "DDL log insert : " << record;
   }