[MDEV-22185] Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON or ER_KEY_NOT_FOUND or Assertion `inited==NONE' failed in handler::ha_index_init Created: 2020-04-07  Updated: 2022-04-26  Resolved: 2020-05-05

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.5
Fix Version/s: 10.5.3

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: affects-tests, regression

Issue Links:
Blocks
Relates
relates to MDEV-22262 Server crashes in ha_partition::open ... Confirmed
relates to MDEV-22424 Server crashes in handler::check_dupl... Closed
relates to MDEV-21540 Initialization of already inited long... Closed
relates to MDEV-22184 UNIQUE key with USING HASH clause cha... Open
relates to MDEV-28095 crash in multi-update and implicit gr... Closed

 Description   

Before closing the issue, please check that test cases from comments are also fixed.

--source include/have_partition.inc
 
 
 
CREATE TABLE t1 (a INT, b INT, UNIQUE (b) USING HASH) PARTITION BY KEY (a) PARTITIONS 2;
 
INSERT INTO t1 VALUES (1,10),(2,20);
 
UPDATE t1 SET b = 30 LIMIT 1;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.5 dcc2eaeb debug

 
mariadbd: /data/src/10.5/sql/handler.h:3291: int handler::ha_index_init(uint, bool): Assertion `inited==NONE' failed.
 
200407 19:29:03 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fae300ba102 in __GI___assert_fail (assertion=0x561a7264a720 "inited==NONE", file=0x561a7264a6a0 "/data/src/10.5/sql/handler.h", line=3291, function=0x561a72658800 <handler::ha_index_init(unsigned int, bool)::__PRETTY_FUNCTION__> "int handler::ha_index_init(uint, bool)") at assert.c:101
 
#8  0x0000561a70503d4e in handler::ha_index_init (this=0x61d0001e4728, idx=0, sorted=false) at /data/src/10.5/sql/handler.h:3291
 
#9  0x0000561a70ea688e in handler::check_duplicate_long_entry_key (this=0x61d0001e4728, new_rec=0x619000089458 "\361\001", key_no=0) at /data/src/10.5/sql/handler.cc:6589
 
#10 0x0000561a70ea853a in handler::check_duplicate_long_entries_update (this=0x61d0001e4728, new_rec=0x619000089458 "\361\001") at /data/src/10.5/sql/handler.cc:6721
 
#11 0x0000561a70eab863 in handler::ha_update_row (this=0x61d0001e4728, old_data=0x619000089470 "\361\001", new_data=0x619000089458 "\361\001") at /data/src/10.5/sql/handler.cc:6995
 
#12 0x0000561a7171cce8 in ha_partition::update_row (this=0x61d0001e3d28, old_data=0x619000089470 "\361\001", new_data=0x619000089458 "\361\001") at /data/src/10.5/sql/ha_partition.cc:4444
 
#13 0x0000561a70eabb6d in handler::ha_update_row (this=0x61d0001e3d28, old_data=0x619000089470 "\361\001", new_data=0x619000089458 "\361\001") at /data/src/10.5/sql/handler.cc:7000
 
#14 0x0000561a709a1e6c in mysql_update (thd=0x62b000069288, table_list=0x62b0000383c0, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=1, ignore=false, found_return=0x7fae27759cd0, updated_return=0x7fae27759d10) at /data/src/10.5/sql/sql_update.cc:1055
 
#15 0x0000561a706bb609 in mysql_execute_command (thd=0x62b000069288) at /data/src/10.5/sql/sql_parse.cc:4363
 
#16 0x0000561a706d5125 in mysql_parse (thd=0x62b000069288, rawbuf=0x62b0000382a8 "UPDATE t1 SET b = 30 LIMIT 1", length=28, parser_state=0x7fae2775aa50, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7953
 
#17 0x0000561a706aaf15 in dispatch_command (command=COM_QUERY, thd=0x62b000069288, packet=0x629000249289 "UPDATE t1 SET b = 30 LIMIT 1", packet_length=28, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1839
 
#18 0x0000561a706a794a in do_command (thd=0x62b000069288) at /data/src/10.5/sql/sql_parse.cc:1358
 
#19 0x0000561a70ac6a8b in do_handle_one_connection (connect=0x61100001fd88, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#20 0x0000561a70ac6326 in handle_one_connection (arg=0x61100001fc48) at /data/src/10.5/sql/sql_connect.cc:1319
 
#21 0x0000561a71764bc6 in pfs_spawn_thread (arg=0x616000009108) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#22 0x00007fae30934fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#23 0x00007fae301834cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.5 dcc2eaeb non-debug

 
query 'UPDATE t1 SET b = 30 LIMIT 1' failed: 1032: Can't find record in 't1'

The failures started happening on 10.5 after this commit:

commit 0515577d128318e1b62511846d88d0c56226168d
 
Author: Sergei Golubchik
 
Date:   Thu Mar 5 19:19:57 2020 +0100
 
 
 
    cleanup: prepare "update_handler" for WITHOUT OVERLAPS



 Comments   
Comment by Elena Stepanova [ 2020-04-30 ]

With InnoDB the same test case causes another assertion failure on a non-debug build:

--source include/have_partition.inc
 
--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (a INT, b INT, UNIQUE (b) USING HASH) ENGINE=InnoDB PARTITION BY KEY (a) PARTITIONS 2;
 
INSERT INTO t1 VALUES (1,10),(2,20);
 
UPDATE t1 SET b = 30 LIMIT 1;
 
 
 
# Cleanup
 
 
 
DROP TABLE t1;

10.5 RelWithDebInfo 5193c1b5

 
2020-04-30 15:06:48 0x7f65ed361700  InnoDB: Assertion failure in file /data/src/10.5/storage/innobase/row/row0mysql.cc line 1854
 
InnoDB: Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON
 
 
 
#6  0x0000560c4bca0303 in ut_dbg_assertion_failed (expr=expr@entry=0x560c4c7436d0 "node->pcur->rel_pos == BTR_PCUR_ON", file=file@entry=0x560c4c742f38 "/data/src/10.5/storage/innobase/row/row0mysql.cc", line=line@entry=1854) at /data/src/10.5/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x0000560c4c2e758f in row_update_for_mysql (prebuilt=0x7f65bc103d50) at /data/src/10.5/storage/innobase/row/row0mysql.cc:1854
 
#8  0x0000560c4c231e50 in ha_innobase::update_row (this=0x7f65bc0f9550, old_row=0x7f65bc103898 "\361\001", new_row=0x7f65bc103880 "\361\001") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8552
 
#9  0x0000560c4bf839a2 in handler::ha_update_row (this=0x7f65bc0f9550, old_data=old_data@entry=0x7f65bc103898 "\361\001", new_data=new_data@entry=0x7f65bc103880 "\361\001") at /data/src/10.5/sql/handler.cc:7017
 
#10 0x0000560c4c19126e in ha_partition::update_row (this=0x7f65bc0e97e0, old_data=0x7f65bc103898 "\361\001", new_data=0x7f65bc103880 "\361\001") at /data/src/10.5/sql/ha_partition.cc:4510
 
#11 0x0000560c4bf83898 in handler::ha_update_row (this=0x7f65bc0e97e0, old_data=0x7f65bc103898 "\361\001", new_data=0x7f65bc103880 "\361\001") at /data/src/10.5/sql/handler.cc:7017
 
#12 0x0000560c4be3c97b in mysql_update (thd=thd@entry=0x7f65bc0009b8, table_list=<optimized out>, fields=..., values=..., conds=<optimized out>, order_num=<optimized out>, order=<optimized out>, limit=1, ignore=false, found_return=0x7f65ed3600d0, updated_return=0x7f65ed3601a0) at /data/src/10.5/sql/sql_update.cc:1059
 
#13 0x0000560c4bd99867 in mysql_execute_command (thd=thd@entry=0x7f65bc0009b8) at /data/src/10.5/sql/sql_parse.cc:4370
 
#14 0x0000560c4bd9ec3b in mysql_parse (thd=thd@entry=0x7f65bc0009b8, rawbuf=<optimized out>, length=28, parser_state=parser_state@entry=0x7f65ed360550, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:7957
 
#15 0x0000560c4bd9480d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f65bc0009b8, packet=packet@entry=0x7f65bc007c69 "UPDATE t1 SET b = 30 LIMIT 1", packet_length=packet_length@entry=28, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:1840
 
#16 0x0000560c4bd92c61 in do_command (thd=0x7f65bc0009b8) at /data/src/10.5/sql/sql_parse.cc:1359
 
#17 0x0000560c4be7a7a4 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x560c4f6750e8, put_in_cache=put_in_cache@entry=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#18 0x0000560c4be7aaa3 in handle_one_connection (arg=arg@entry=0x560c4f6750e8) at /data/src/10.5/sql/sql_connect.cc:1319
 
#19 0x0000560c4c194ce4 in pfs_spawn_thread (arg=0x560c4f6d2ea8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#20 0x00007f65f5d644a4 in start_thread (arg=0x7f65ed361700) at pthread_create.c:456
 
#21 0x00007f65f3e98d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Comment by Elena Stepanova [ 2020-04-30 ]

Another test case, no partitions, WITHOUT OVERLAPS:

--source include/have_innodb.inc
 
 
 
create table t1 (pk int, s date, e date,  PERIOD FOR se (s,e), PRIMARY KEY (pk,se WITHOUT OVERLAPS)) ENGINE=InnoDB;
 
insert into t1 values (1,'2020-01-01','2020-02-20');
 
delete from t1 for portion of se from '2020-01-30' to '2020-01-31';
 
 
 
# Cleanup
 
drop table t1;

10.5 89aebdf9 RelWithDebInfo

 
2020-05-01 01:24:35 0x7f946011e700  InnoDB: Assertion failure in file /data/src/10.5/storage/innobase/row/row0mysql.cc line 1854
 
InnoDB: Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON
 
 
 
#6  0x000056066dad16e5 in ut_dbg_assertion_failed (expr=expr@entry=0x56066e5756d0 "node->pcur->rel_pos == BTR_PCUR_ON", file=file@entry=0x56066e574f38 "/data/src/10.5/storage/innobase/row/row0mysql.cc", line=line@entry=1854) at /data/src/10.5/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x000056066e118c9f in row_update_for_mysql (prebuilt=0x7f94280fd540) at /data/src/10.5/storage/innobase/row/row0mysql.cc:1854
 
#8  0x000056066e063490 in ha_innobase::update_row (this=0x7f94280f8c40, old_row=0x7f94280fc468 "\377\001", new_row=0x7f94280fc458 "\377\001") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8534
 
#9  0x000056066ddb4eb8 in handler::ha_update_row (this=0x7f94280f8c40, old_data=0x7f94280fc468 "\377\001", new_data=0x7f94280fc458 "\377\001") at /data/src/10.5/sql/handler.cc:7018
 
#10 0x000056066dedcd54 in update_portion_of_time (inside_period=<synthetic pointer>, period_conds=..., table=0x7f94280f9de8, thd=0x7f94280009b8) at /data/src/10.5/sql/sql_delete.cc:259
 
#11 mysql_delete (thd=thd@entry=0x7f94280009b8, table_list=0x7f9428010438, conds=<optimized out>, order_list=order_list@entry=0x7f94280052a8, limit=18446744073709551615, options=<optimized out>, result=0x0) at /data/src/10.5/sql/sql_delete.cc:788
 
#12 0x000056066dbcac7a in mysql_execute_command (thd=thd@entry=0x7f94280009b8) at /data/src/10.5/sql/sql_parse.cc:4749
 
#13 0x000056066dbd01fb in mysql_parse (thd=thd@entry=0x7f94280009b8, rawbuf=<optimized out>, length=66, parser_state=parser_state@entry=0x7f946011d550, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:7957
 
#14 0x000056066dbc5dcd in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f94280009b8, packet=packet@entry=0x7f9428007c69 "delete from t1 for portion of se from '2020-01-30' to '2020-01-31'", packet_length=packet_length@entry=66, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.5/sql/sql_parse.cc:1840
 
#15 0x000056066dbc4221 in do_command (thd=0x7f94280009b8) at /data/src/10.5/sql/sql_parse.cc:1359
 
#16 0x000056066dcabdb4 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x560670995258, put_in_cache=put_in_cache@entry=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#17 0x000056066dcac0b3 in handle_one_connection (arg=arg@entry=0x560670995258) at /data/src/10.5/sql/sql_connect.cc:1319
 
#18 0x000056066dfc6484 in pfs_spawn_thread (arg=0x560670996688) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#19 0x00007f9468b214a4 in start_thread (arg=0x7f946011e700) at pthread_create.c:456
 
#20 0x00007f9466c55d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

10.5 89aebdf9 debug

 
mariadbd: /data/src/10.5/sql/handler.h:3314: int handler::ha_index_init(uint, bool): Assertion `inited==NONE' failed.
 
200501  1:25:40 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f5c1b057f12 in __GI___assert_fail (assertion=0x55dfe09ef39e "inited==NONE", file=0x55dfe09ef373 "/data/src/10.5/sql/handler.h", line=3314, function=0x55dfe09f34e0 <handler::ha_index_init(unsigned int, bool)::__PRETTY_FUNCTION__> "int handler::ha_index_init(uint, bool)") at assert.c:101
 
#8  0x000055dfdfbaef25 in handler::ha_index_init (this=0x7f5bd80faeb0, idx=0, sorted=false) at /data/src/10.5/sql/handler.h:3314
 
#9  0x000055dfdffcc087 in handler::ha_check_overlaps (this=0x7f5bd80faeb0, old_data=0x7f5bd8221b48 "\377\001", new_data=0x7f5bd8221b38 "\377\001") at /data/src/10.5/sql/handler.cc:6798
 
#10 0x000055dfdffcd0ec in handler::ha_update_row (this=0x7f5bd80faeb0, old_data=0x7f5bd8221b48 "\377\001", new_data=0x7f5bd8221b38 "\377\001") at /data/src/10.5/sql/handler.cc:7006
 
#11 0x000055dfe01925de in update_portion_of_time (thd=0x7f5bd8000b18, table=0x7f5bd80fa038, period_conds=..., inside_period=0x7f5c145dd500) at /data/src/10.5/sql/sql_delete.cc:259
 
#12 0x000055dfe019463f in mysql_delete (thd=0x7f5bd8000b18, table_list=0x7f5bd8013a88, conds=0x7f5bd8014f38, order_list=0x7f5bd80055c8, limit=18446744073709551615, options=0, result=0x0) at /data/src/10.5/sql/sql_delete.cc:788
 
#13 0x000055dfdfc68877 in mysql_execute_command (thd=0x7f5bd8000b18) at /data/src/10.5/sql/sql_parse.cc:4749
 
#14 0x000055dfdfc732c6 in mysql_parse (thd=0x7f5bd8000b18, rawbuf=0x7f5bd8013950 "delete from t1 for portion of se from '2020-01-30' to '2020-01-31'", length=66, parser_state=0x7f5c145de520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7957
 
#15 0x000055dfdfc5f5ce in dispatch_command (command=COM_QUERY, thd=0x7f5bd8000b18, packet=0x7f5bd80086a9 "delete from t1 for portion of se from '2020-01-30' to '2020-01-31'", packet_length=66, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1840
 
#16 0x000055dfdfc5dd60 in do_command (thd=0x7f5bd8000b18) at /data/src/10.5/sql/sql_parse.cc:1359
 
#17 0x000055dfdfe01396 in do_handle_one_connection (connect=0x55dfe48e7af8, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#18 0x000055dfdfe010c5 in handle_one_connection (arg=0x55dfe48e7af8) at /data/src/10.5/sql/sql_connect.cc:1319
 
#19 0x000055dfe0336966 in pfs_spawn_thread (arg=0x55dfe4877958) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#20 0x00007f5c1cfe04a4 in start_thread (arg=0x7f5c145df700) at pthread_create.c:456
 
#21 0x00007f5c1b114d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

When the table has more than one row, DELETE causes the same assertion failure on a debug build. Non-debug build doesn't crash, but it produces a duplicate key error, which of course shouldn't happen.

Comment by Elena Stepanova [ 2020-05-01 ]

Raised to blocker due to the last test case – it is the very basic functionality of the new feature, the bug makes it unusable.
Hopefully the fix will also fix MDEV-22424 which should otherwise be a blocker as well.

Generated at Thu Feb 08 09:12:50 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.