[MDEV-19449] 1030: Got error 168 "Unknown (generic) error from engine" for valid TRUNCATE (temporary) TABLE - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.2.24
Fix Version/s: 10.2.25
Component/s: Data Definition - Temporary, Storage Engine - InnoDB
Labels:
- affects-tests-10.2

Description

...

CREATE TEMPORARY TABLE t1 (col1 BIGINT NULL) ENGINE = InnoDB;

INSERT INTO t1 ( k ) SELECT id FROM t1 ;

ERROR 42S22: Unknown column 'id' in 'field list'

TRUNCATE TABLE t1 ;

ALTER TABLE t1 CHANGE COLUMN id col2 BIGINT NULL;

ERROR 42S22: Unknown column 'id' in 't1'

TRUNCATE TABLE t1 ;

main.ml_19 'innodb'                      [ fail ]

        Test ended at 2019-05-13 13:56:45

CURRENT_TEST: main.ml_19

mysqltest: At line 10: query 'TRUNCATE TABLE t1 ' failed: 1030: Got error 168 "Unknown (generic) error from engine" from storage engine InnoDB

10.2.25 commit 8ce702aa90c174566f4ac950e85cc7570bf9b647

10.2.24 commit b30bbb7d9a1c3855c901b74735660e49ab64a2a8 2019-03-25

No issue in

10.3.15 commit 0c188d5efc452b576c46270e65b9db4746ee9dfe (pull 2019-05-13)

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

ml_19.test
0.3 kB
2019-05-13 11:58

Issue Links

is caused by

MDEV-13564 TRUNCATE TABLE and undo tablespace truncation are not compatible with Mariabackup

Closed

relates to

MDEV-17167 InnoDB: Failing assertion: table->get_ref_count() == 0 upon truncating a temporary table

Closed

Activity

Ascending order - Click to sort in descending order

Anel Husakovic added a comment - 2019-05-13 13:22

It seems like table is "locked".
Here is bt from gdb:

2019-05-13  6:16:24 140736932443904 [ERROR] InnoDB: Cannot rename table 'tmp/#sql-ib30' to 'tmp/#sql-ib30' since the dictionary cache already contains 'tmp/#sql-ib30'.

Thread 32 "mysqld" hit Breakpoint 1, my_message_sql (error=1030, str=0x7fffdedd4330 "Got error 168 \"Unknown (generic) error from engine\" from storage engine InnoDB", MyFlags=0) at sql/mysqld.cc:3612

(gdb) bt

#0  my_message_sql (error=1030, str=0x7fffdedd4330 "Got error 168 \"Unknown (generic) error from engine\" from storage engine InnoDB", MyFlags=0) at sql/mysqld.cc:3612

#1  0x00005555564d563d in my_error (nr=1030, MyFlags=0) at mysys/my_error.c:125

#2  0x0000555555d9937d in handler::print_error (this=0x7fff6801e880, error=168, errflag=0) at sql/handler.cc:3735

#3  0x0000555555f5e17e in Sql_cmd_truncate_table::handler_truncate (this=0x7fff68010d98, thd=0x7fff68000cf8, table_ref=0x7fff68010780, is_tmp_table=true) at sql/sql_truncate.cc:244

#4  0x0000555555f5e637 in Sql_cmd_truncate_table::truncate_table (this=0x7fff68010d98, thd=0x7fff68000cf8, table_ref=0x7fff68010780) at sql/sql_truncate.cc:399

#5  0x0000555555f5e912 in Sql_cmd_truncate_table::execute (this=0x7fff68010d98, thd=0x7fff68000cf8) at sql/sql_truncate.cc:495

#6  0x0000555555b1d6a3 in mysql_execute_command (thd=0x7fff68000cf8) at sql/sql_parse.cc:6233

#7  0x0000555555b227de in mysql_parse (thd=0x7fff68000cf8, rawbuf=0x7fff680106b0 "TRUNCATE TABLE t1", length=17, parser_state=0x7fffdedd6230, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8020

#8  0x0000555555b1000e in dispatch_command (command=COM_QUERY, thd=0x7fff68000cf8, packet=0x7fff680083f9 "TRUNCATE TABLE t1", packet_length=17, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1832

#9  0x0000555555b0e964 in do_command (thd=0x7fff68000cf8) at sql/sql_parse.cc:1386

#10 0x0000555555c616c9 in do_handle_one_connection (connect=0x5555579aea58) at sql/sql_connect.cc:1335

#11 0x0000555555c61449 in handle_one_connection (arg=0x5555579aea58) at sql/sql_connect.cc:1241

#12 0x00007ffff72f26db in start_thread (arg=0x7fffdedd7700) at pthread_create.c:463

#13 0x00007ffff66dc88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Anel Husakovic added a comment - 2019-05-13 13:22 It seems like table is "locked". Here is bt from gdb: 2019-05-13 6:16:24 140736932443904 [ERROR] InnoDB: Cannot rename table 'tmp/#sql-ib30' to 'tmp/#sql-ib30' since the dictionary cache already contains 'tmp/#sql-ib30'. Thread 32 "mysqld" hit Breakpoint 1, my_message_sql (error=1030, str=0x7fffdedd4330 "Got error 168 \"Unknown (generic) error from engine\" from storage engine InnoDB", MyFlags=0) at sql/mysqld.cc:3612 (gdb) bt #0 my_message_sql (error=1030, str=0x7fffdedd4330 "Got error 168 \"Unknown (generic) error from engine\" from storage engine InnoDB", MyFlags=0) at sql/mysqld.cc:3612 #1 0x00005555564d563d in my_error (nr=1030, MyFlags=0) at mysys/my_error.c:125 #2 0x0000555555d9937d in handler::print_error (this=0x7fff6801e880, error=168, errflag=0) at sql/handler.cc:3735 #3 0x0000555555f5e17e in Sql_cmd_truncate_table::handler_truncate (this=0x7fff68010d98, thd=0x7fff68000cf8, table_ref=0x7fff68010780, is_tmp_table=true) at sql/sql_truncate.cc:244 #4 0x0000555555f5e637 in Sql_cmd_truncate_table::truncate_table (this=0x7fff68010d98, thd=0x7fff68000cf8, table_ref=0x7fff68010780) at sql/sql_truncate.cc:399 #5 0x0000555555f5e912 in Sql_cmd_truncate_table::execute (this=0x7fff68010d98, thd=0x7fff68000cf8) at sql/sql_truncate.cc:495 #6 0x0000555555b1d6a3 in mysql_execute_command (thd=0x7fff68000cf8) at sql/sql_parse.cc:6233 #7 0x0000555555b227de in mysql_parse (thd=0x7fff68000cf8, rawbuf=0x7fff680106b0 "TRUNCATE TABLE t1", length=17, parser_state=0x7fffdedd6230, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8020 #8 0x0000555555b1000e in dispatch_command (command=COM_QUERY, thd=0x7fff68000cf8, packet=0x7fff680083f9 "TRUNCATE TABLE t1", packet_length=17, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1832 #9 0x0000555555b0e964 in do_command (thd=0x7fff68000cf8) at sql/sql_parse.cc:1386 #10 0x0000555555c616c9 in do_handle_one_connection (connect=0x5555579aea58) at sql/sql_connect.cc:1335 #11 0x0000555555c61449 in handle_one_connection (arg=0x5555579aea58) at sql/sql_connect.cc:1241 #12 0x00007ffff72f26db in start_thread (arg=0x7fffdedd7700) at pthread_create.c:463 #13 0x00007ffff66dc88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Matthias Leich added a comment - 2019-05-13 14:01

Hi Anel,

yes, some superfluous lock would quite good fit to my observations during simplification of the test.

I tried to omit the INSERT and the ALTER (both fail anyway) but than the bad effect simply disappeared.

Matthias Leich added a comment - 2019-05-13 14:01 Hi Anel, yes, some superfluous lock would quite good fit to my observations during simplification of the test. I tried to omit the INSERT and the ALTER (both fail anyway) but than the bad effect simply disappeared.

Marko Mäkelä added a comment - 2019-05-13 16:13

Note: TEMPORARY TABLE never uses native ALTER TABLE, always ALGORITHM=COPY.

I suspect that something in ALTER TABLE is corrupting the handler::table_share so that TRUNCATE in InnoDB fails (and preserves the old contents of the table).

Marko Mäkelä added a comment - 2019-05-13 16:13 Note: TEMPORARY TABLE never uses native ALTER TABLE , always ALGORITHM=COPY . I suspect that something in ALTER TABLE is corrupting the handler::table_share so that TRUNCATE in InnoDB fails (and preserves the old contents of the table).

Marko Mäkelä added a comment - 2019-05-13 17:08

I missed the following message:

2019-05-13  6:16:24 140736932443904 [ERROR] InnoDB: Cannot rename table 'tmp/#sql-ib30' to 'tmp/#sql-ib30' since the dictionary cache already contains 'tmp/#sql-ib30'.

The ml_19.test essentially performs two TRUNCATE for a temporary table. For some reason, the simplified variant will not fail:

CREATE TEMPORARY TABLE t1 (col1 BIGINT NULL) ENGINE = InnoDB;

TRUNCATE TABLE t1;

TRUNCATE TABLE t1;

Also, the test failed to reproduce the problem with 10.3 for me.

In any case, the TRUNCATE of TEMPORARY TABLE should avoid renaming the table. It should suffice to simply drop and create the table.

Marko Mäkelä added a comment - 2019-05-13 17:08 I missed the following message: 2019-05-13 6:16:24 140736932443904 [ERROR] InnoDB: Cannot rename table 'tmp/#sql-ib30' to 'tmp/#sql-ib30' since the dictionary cache already contains 'tmp/#sql-ib30'. The ml_19.test essentially performs two TRUNCATE for a temporary table. For some reason, the simplified variant will not fail: CREATE TEMPORARY TABLE t1 (col1 BIGINT NULL ) ENGINE = InnoDB; TRUNCATE TABLE t1; TRUNCATE TABLE t1; Also, the test failed to reproduce the problem with 10.3 for me. In any case, the TRUNCATE of TEMPORARY TABLE should avoid renaming the table. It should suffice to simply drop and create the table.

Marko Mäkelä added a comment - 2019-05-14 10:08

I did some more debugging. I am afraid that the problem could be unique to the 10.2 series.

If I remember correctly, MariaDB 10.3 allows multiple concurrent handles to temporary tables, but 10.2 is not supposed to allow that. The problem appears to be that at the time the TRUNCATE executes, there will be multiple open table handles to the temporary table. ~~MDEV-13564~~ expects there to be only the current table handle. You can set a breakpoint and see the large reference counts:

break dict_table_rename_in_cache

run

display table->n_ref_count

display table->name

continue

The problem occurs when a table is renamed from the same name (#sql-ib19 in my case) to the same name. That should not be possible, but apparently an extraneous table handle for the temporary table is still referring to the temporary table before the first TRUNCATE TABLE operation. Because of the background drop queue, that table was not dropped yet, and also AddressSanitizer does not notice any foul play.

Here is a slightly edited and commented version of ml_19.test that reproduces the problem:

--source include/have_innodb.inc

CREATE TEMPORARY TABLE t1 (col1 BIGINT NULL) ENGINE = InnoDB;

--error ER_BAD_FIELD_ERROR

INSERT INTO t1 (no_such_col) SELECT * FROM t1;

--echo # the bogus column name can be before or after SELECT, or both

TRUNCATE TABLE t1 ;

--error ER_BAD_FIELD_ERROR

ALTER TABLE t1 CHANGE no_such_col1 col1 BIGINT NULL;

--echo # MODIFY no_such_col BIGINT NULL will not cause the failure

TRUNCATE TABLE t1 ;

--echo # wrongly tried to re-truncate the old table from before the first TRUNCATE

Marko Mäkelä added a comment - 2019-05-14 10:08 I did some more debugging. I am afraid that the problem could be unique to the 10.2 series. If I remember correctly, MariaDB 10.3 allows multiple concurrent handles to temporary tables, but 10.2 is not supposed to allow that. The problem appears to be that at the time the TRUNCATE executes, there will be multiple open table handles to the temporary table. MDEV-13564 expects there to be only the current table handle. You can set a breakpoint and see the large reference counts: break dict_table_rename_in_cache run display table->n_ref_count display table->name continue The problem occurs when a table is renamed from the same name ( #sql-ib19 in my case) to the same name. That should not be possible, but apparently an extraneous table handle for the temporary table is still referring to the temporary table before the first TRUNCATE TABLE operation. Because of the background drop queue, that table was not dropped yet, and also AddressSanitizer does not notice any foul play. Here is a slightly edited and commented version of ml_19.test that reproduces the problem: --source include/have_innodb.inc CREATE TEMPORARY TABLE t1 (col1 BIGINT NULL ) ENGINE = InnoDB; --error ER_BAD_FIELD_ERROR INSERT INTO t1 (no_such_col) SELECT * FROM t1; --echo # the bogus column name can be before or after SELECT, or both TRUNCATE TABLE t1 ; --error ER_BAD_FIELD_ERROR ALTER TABLE t1 CHANGE no_such_col1 col1 BIGINT NULL ; --echo # MODIFY no_such_col BIGINT NULL will not cause the failure TRUNCATE TABLE t1 ; --echo # wrongly tried to re-truncate the old table from before the first TRUNCATE

Marko Mäkelä added a comment - 2019-05-14 10:33

Backporting (cherry-picking) the ~~MDEV-17167~~ fix to 10.2 fixes this test case.

Marko Mäkelä added a comment - 2019-05-14 10:33 Backporting (cherry-picking) the MDEV-17167 fix to 10.2 fixes this test case.

Marko Mäkelä added a comment - 2019-05-14 11:49

I tried the test case on 10.3 with the ~~MDEV-17167~~ fix reverted, and it reproduces the ~~MDEV-17167~~ assertion failure:

10.3 5c93509aad6aa952c48f078557c86322dfc35692 after git revert bad2f1569da57c4a81cc84ec2f4a79924df9c8d6
InnoDB: Failing assertion: table->get_ref_count() == 0
…
#7 0x00005564064216c5 in dict_table_remove_from_cache_low (table=0x7f0698006be8, lru_evict=0) at /mariadb/10.3/storage/innobase/dict/dict0dict.cc:1978
#8 0x0000556406421e61 in dict_table_remove_from_cache (table=0x7f0698006be8) at /mariadb/10.3/storage/innobase/dict/dict0dict.cc:2061
#9 0x00005564062ab5b0 in row_drop_table_for_mysql (name=0x7f07086f1440 "mysqld.1/#sql-ib20", trx=0x7f07091f21c8, sqlcom=SQLCOM_TRUNCATE, create_failed=false, nonatomic=true) at /mariadb/10.3/storage/innobase/row/row0mysql.cc:3367
#10 0x0000556406171461 in ha_innobase::delete_table (this=0x7f06980a76d0, name=0x7f06980a8d38 "mysqld.1/#sql-ib20", sqlcom=SQLCOM_TRUNCATE) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:12921
#11 0x000055640615d26b in ha_innobase::truncate (this=0x7f06980a76d0) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:13342

Marko Mäkelä added a comment - 2019-05-14 11:49 I tried the test case on 10.3 with the MDEV-17167 fix reverted, and it reproduces the MDEV-17167 assertion failure: 10.3 5c93509aad6aa952c48f078557c86322dfc35692 after git revert bad2f1569da57c4a81cc84ec2f4a79924df9c8d6 InnoDB: Failing assertion: table->get_ref_count() == 0 … #7 0x00005564064216c5 in dict_table_remove_from_cache_low (table=0x7f0698006be8, lru_evict=0) at /mariadb/10.3/storage/innobase/dict/dict0dict.cc:1978 #8 0x0000556406421e61 in dict_table_remove_from_cache (table=0x7f0698006be8) at /mariadb/10.3/storage/innobase/dict/dict0dict.cc:2061 #9 0x00005564062ab5b0 in row_drop_table_for_mysql (name=0x7f07086f1440 "mysqld.1/#sql-ib20", trx=0x7f07091f21c8, sqlcom=SQLCOM_TRUNCATE, create_failed=false, nonatomic=true) at /mariadb/10.3/storage/innobase/row/row0mysql.cc:3367 #10 0x0000556406171461 in ha_innobase::delete_table (this=0x7f06980a76d0, name=0x7f06980a8d38 "mysqld.1/#sql-ib20", sqlcom=SQLCOM_TRUNCATE) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:12921 #11 0x000055640615d26b in ha_innobase::truncate (this=0x7f06980a76d0) at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:13342

People

Assignee:: Marko Mäkelä

Reporter:: Matthias Leich

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2019-05-13 11:58

Updated:: 2019-05-14 13:30

Resolved:: 2019-05-14 13:30

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration