[MDEV-22785] Crash with prepared statements and NEXTVAL() Created: 2020-06-03  Updated: 2022-08-03  Resolved: 2021-08-26

Status: Closed
Project: MariaDB Server
Component/s: Prepared Statements, Sequences
Affects Version/s: 10.4.12, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.3.32, 10.4.22, 10.5.13, 10.6.5

Type: Bug Priority: Major
Reporter: Karsten Budde Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: crash
Environment:

CentOS Linux 7.7.1908


Issue Links:
Relates
relates to MDEV-20074 Lost connection on update trigger Closed
relates to MDEV-28612 Server crash caused by concurrent ins... Open
relates to MDEV-28650 Server crashes in Item_func_nextval::... Confirmed

 Description   

Update: Test case is in the comments.


Hello,

mariaDB crashed with signal 11. Can you help me, to find out the cause?

Regards,
Karsten

Here the part from log:

Jun  3 08:24:21 hw4serv mysqld: 200603  8:24:21 [ERROR] mysqld got signal 11 ;
Jun  3 08:24:21 hw4serv mysqld: This could be because you hit a bug. It is also possible that this binary
Jun  3 08:24:21 hw4serv mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Jun  3 08:24:21 hw4serv mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Jun  3 08:24:21 hw4serv mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Jun  3 08:24:21 hw4serv mysqld: We will try our best to scrape up some info that will hopefully help
Jun  3 08:24:21 hw4serv mysqld: diagnose the problem, but since we have already crashed,
Jun  3 08:24:21 hw4serv mysqld: something is definitely wrong and this may fail.
Jun  3 08:24:21 hw4serv mysqld: Server version: 10.4.12-MariaDB-log
Jun  3 08:24:21 hw4serv mysqld: key_buffer_size=134217728
Jun  3 08:24:21 hw4serv mysqld: read_buffer_size=131072
Jun  3 08:24:21 hw4serv mysqld: max_used_connections=16
Jun  3 08:24:21 hw4serv mysqld: max_threads=153
Jun  3 08:24:21 hw4serv mysqld: thread_count=23
Jun  3 08:24:21 hw4serv mysqld: It is possible that mysqld could use up to
Jun  3 08:24:21 hw4serv mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467752 K  bytes of memory
Jun  3 08:24:21 hw4serv mysqld: Hope that's ok; if not, decrease some variables in the equation.
Jun  3 08:24:21 hw4serv mysqld: Thread pointer: 0x7f8d040009a8
Jun  3 08:24:21 hw4serv mysqld: Attempting backtrace. You can use the following information to find out
Jun  3 08:24:21 hw4serv mysqld: where mysqld died. If you see no messages after this, something went
Jun  3 08:24:21 hw4serv mysqld: terribly wrong...
Jun  3 08:24:21 hw4serv mysqld: stack_bottom = 0x7f8dcca87cf0 thread_stack 0x49000
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55cdff784a1e]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x55cdff218d8f]
Jun  3 08:24:21 hw4serv mysqld: sigaction.c:0(__restore_rt)[0x7f8dea9785f0]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN17Item_func_nextval7val_intEv+0xa6)[0x55cdff289346]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN4Item17save_int_in_fieldEP5Fieldb+0x1f)[0x55cdff23e9cf]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN4Item13save_in_fieldEP5Fieldb+0x36)[0x55cdff22ff86]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN5TABLE21update_default_fieldsEb+0xad)[0x55cdff0c632d]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z11fill_recordP3THDP5TABLER4ListI4ItemES6_bb+0x40e)[0x55cdfefa9bfe]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z36fill_record_n_invoke_before_triggersP3THDP5TABLER4ListI4ItemES6_b14trg_event_type+0x39)[0x55cdfefa9d89]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x11cd)[0x55cdfefd6b6d]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3dd2)[0x55cdff005c52]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN13sp_instr_stmt9exec_coreEP3THDPj+0x36)[0x55cdfef68c26]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN13sp_lex_keeper23reset_lex_and_exec_coreEP3THDPjbP8sp_instr+0x155)[0x55cdfef713a5]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN13sp_instr_stmt7executeEP3THDPj+0x64c)[0x55cdfef71e2c]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN7sp_head7executeEP3THDb+0xa64)[0x55cdfef6cb94]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN7sp_head17execute_procedureEP3THDP4ListI4ItemE+0x779)[0x55cdfef6e2e9]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(+0x69f18a)[0x55cdfeffa18a]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(+0x6a0a46)[0x55cdfeffba46]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN12Sql_cmd_call7executeEP3THD+0x90)[0x55cdfeffc260]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x27c8)[0x55cdff004648]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x4b6)[0x55cdff01ecc6]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x92)[0x55cdff01ee82]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(+0x6c47e7)[0x55cdff01f7e7]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDPcj+0x27)[0x55cdff01f877]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x17f5)[0x55cdff00df85]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z10do_commandP3THD+0x11c)[0x55cdff00fa4c]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1fa)[0x55cdff0ee32a]
Jun  3 08:24:21 hw4serv mysqld: /usr/sbin/mysqld(handle_one_connection+0x3d)[0x55cdff0ee40d]
Jun  3 08:24:21 hw4serv mysqld: pthread_create.c:0(start_thread)[0x7f8dea970e65]
Jun  3 08:24:21 hw4serv mysqld: /lib64/libc.so.6(clone+0x6d)[0x7f8de8d1188d]
Jun  3 08:24:21 hw4serv mysqld: Trying to get some variables.
Jun  3 08:24:21 hw4serv mysqld: Some pointers may be invalid and cause the dump to abort.
Jun  3 08:24:21 hw4serv kernel: mysqld[9540]: segfault at 39e4 ip 000055cdff289346 sp 00007f8dcca800c0 error 4 in mysqld[55cdfe95b000+1483000]
Jun  3 08:24:21 hw4serv mysqld: Query (0x7f8d05292fe0): insert into hzodelivery.deliverJob       (supplier ,clientId ,hierarchyDefId ,ownerId ,obId)      values      ('{"source": "XOIS-Abgleich"}' ,6 , 290 , NAME_CONST('iFirmObId',41069873) , NAME_CONST('iFirmObId',41069873) )
Jun  3 08:24:21 hw4serv mysqld: Connection ID (thread ID): 367077
Jun  3 08:24:21 hw4serv mysqld: Status: NOT_KILLED
Jun  3 08:24:21 hw4serv mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on
Jun  3 08:24:21 hw4serv mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Jun  3 08:24:21 hw4serv mysqld: information that should help you find out what is causing the crash.
Jun  3 08:24:21 hw4serv mysqld: Writing a core file...
Jun  3 08:24:21 hw4serv mysqld: Working directory at /var/lib/mysql
Jun  3 08:24:21 hw4serv mysqld: Resource Limits:
Jun  3 08:24:21 hw4serv mysqld: Limit                     Soft Limit           Hard Limit           Units
Jun  3 08:24:21 hw4serv mysqld: Max cpu time              unlimited            unlimited            seconds
Jun  3 08:24:21 hw4serv mysqld: Max file size             unlimited            unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max data size             unlimited            unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max stack size            8388608              unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max core file size        0                    unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max resident set          unlimited            unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max processes             31204                31204                processes
Jun  3 08:24:21 hw4serv mysqld: Max open files            1048576              1048576              files
Jun  3 08:24:21 hw4serv mysqld: Max locked memory         65536                65536                bytes
Jun  3 08:24:21 hw4serv mysqld: Max address space         unlimited            unlimited            bytes
Jun  3 08:24:21 hw4serv mysqld: Max file locks            unlimited            unlimited            locks
Jun  3 08:24:21 hw4serv mysqld: Max pending signals       31204                31204                signals
Jun  3 08:24:21 hw4serv mysqld: Max msgqueue size         819200               819200               bytes
Jun  3 08:24:22 hw4serv mysqld: Max nice priority         0                    0
Jun  3 08:24:22 hw4serv mysqld: Max realtime priority     0                    0
Jun  3 08:24:22 hw4serv mysqld: Max realtime timeout      unlimited            unlimited            us
Jun  3 08:24:22 hw4serv mysqld: Core pattern: core
Jun  3 08:24:22 hw4serv systemd: mariadb.service: main process exited, code=killed, status=11/SEGV
Jun  3 08:24:22 hw4serv systemd: Unit mariadb.service entered failed state.
Jun  3 08:24:22 hw4serv systemd: mariadb.service failed.
Jun  3 08:24:27 hw4serv systemd: mariadb.service holdoff time over, scheduling restart.
Jun  3 08:24:27 hw4serv systemd: Stopped MariaDB 10.4.12 database server.
Jun  3 08:24:27 hw4serv systemd: Starting MariaDB 10.4.12 database server...
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] /usr/sbin/mysqld (mysqld 10.4.12-MariaDB-log) starting as process 16499 ...
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] mysqld: Aria engine: starting recovery
Jun  3 08:24:27 hw4serv mysqld: recovered pages: 0% 24% 49% 74% 99% 100% (0.0 seconds); tables to flush: 1 0
Jun  3 08:24:27 hw4serv mysqld: (0.0 seconds);
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] mysqld: Aria engine: recovery done
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] CONNECT: Version 1.07.0001 November 12, 2019
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Using Linux native AIO
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Uses event mutexes
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Number of pools: 1
Jun  3 08:24:27 hw4serv mysqld: 2020-06-03  8:24:27 0 [Note] InnoDB: Using SSE2 crc32 instructions
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Completed initialization of buffer pool
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=82779655053
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Transaction 34583871 was in the XA prepared state.
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Trx id counter is 34583872
Jun  3 08:24:28 hw4serv mysqld: 2020-06-03  8:24:28 0 [Note] InnoDB: Starting final batch to recover 339 pages from redo log.
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Last binlog file '/marialogs/binlog.000083', position 397596788
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Rollback of non-prepared transactions completed
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Waiting for purge to start
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: 10.4.12 started; log sequence number 82779988762; transaction id 34583874
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] Plugin 'FEEDBACK' is disabled.
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [ERROR] mysqld: Plugin 'CONNECT' already installed
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [ERROR] mysqld: Plugin 'FEDERATED' already installed
Jun  3 08:24:29 hw4serv mysqld: 2020-06-03  8:24:29 0 [Note] Recovering after a crash using /marialogs/binlog
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] Starting crash recovery...
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] InnoDB: Starting recovery for XA transactions...
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] InnoDB: Transaction 34583871 in prepared state after recovery
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] InnoDB: Transaction contains changes to 1 rows
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] InnoDB: 1 transactions in prepared state after recovery
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] Found 1 prepared transaction(s) in InnoDB
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] Crash recovery finished.
Jun  3 08:24:34 hw4serv mysqld: 2020-06-03  8:24:34 0 [Note] Server socket created on IP: '::'.
Jun  3 08:24:35 hw4serv mysqld: 2020-06-03  8:24:35 0 [Note] Reading of all Master_info entries succeeded
Jun  3 08:24:35 hw4serv mysqld: 2020-06-03  8:24:35 0 [Note] Added new Master_info '' to hash table
Jun  3 08:24:35 hw4serv mysqld: 2020-06-03  8:24:35 0 [Note] /usr/sbin/mysqld: ready for connections.
Jun  3 08:24:35 hw4serv mysqld: Version: '10.4.12-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
Jun  3 08:24:35 hw4serv systemd: Started MariaDB 10.4.12 database server.
Jun  3 08:24:35 hw4serv mysqld: 2020-06-03  8:24:35 13 [Note] Detected table cache mutex contention at instance 1: 34% waits. Additional table cache instance activated. Number of instances after activation: 2.
Jun  3 08:24:50 hw4serv mysqld: 2020-06-03  8:24:50 0 [Note] InnoDB: Buffer pool(s) load completed at 200603  8:24:50



 Comments   
Comment by Daniel Black [ 2020-06-03 ]

can you include SHOW CREATE TABLE hzodelivery.deliverJob and the SHOW CREATE TRIGGER xxxx for the triggers on this table? There's a sequence related to this right? Can you include its definition too?

Comment by Karsten Budde [ 2020-06-03 ]

here the ddl-statements:

table deliverJob

CREATE TABLE `deliverJob` (
`id` int(10) unsigned NOT NULL DEFAULT nextval(`hzodelivery`.`seqDeliverJob`) ,
`supplier` text NOT NULL ,
`clientId` int(10) unsigned NOT NULL DEFAULT 5 ,
`hierarchyDefId` int(10) unsigned NOT NULL ,
`ownerId` int(10) unsigned NOT NULL ,
`obId` int(10) unsigned NOT NULL ,
`workStatus` char(1) NOT NULL DEFAULT 'N' ,
`newDate` timestamp(6) NOT NULL DEFAULT current_timestamp(6) ,
`changeDate` timestamp(6) NOT NULL DEFAULT current_timestamp(6) ON UPDATE current_timestamp(6) ,
PRIMARY KEY (`id`),
KEY `deliverJob_object_FK` (`obId`),
KEY `deliverJob_workStatus_IDX` (`workStatus`,`clientId`,`hierarchyDefId`,`ownerId`) USING BTREE,
CONSTRAINT `deliverJob_object_FK` FOREIGN KEY (`obId`) REFERENCES `object` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4

there are no trigger on table deliverJob.
do you need also the table definition for table object?

sequence-definition:

CREATE TABLE `seqDeliverJob` (
`next_not_cached_value` bigint(21) NOT NULL,
`minimum_value` bigint(21) NOT NULL,
`maximum_value` bigint(21) NOT NULL,
`start_value` bigint(21) NOT NULL ,
`increment` bigint(21) NOT NULL ,
`cache_size` bigint(21) unsigned NOT NULL,
`cycle_option` tinyint(1) unsigned NOT NULL ,
`cycle_count` bigint(21) NOT NULL
) ENGINE=InnoDB SEQUENCE=1

sequence-values:

Name |Value
--------------------- |-------------------
next_not_cached_value|758801
minimum_value |1
maximum_value |9223372036854775806
start_value |1
increment |1
cache_size |100
cycle_option |0
cycle_count |0

Comment by Elena Stepanova [ 2020-07-08 ]

Thanks for the report.

CREATE SEQUENCE s;
CREATE TABLE t1 (id int NOT NULL DEFAULT NEXTVAL(s), PRIMARY KEY (id));
PREPARE stmt FROM " INSERT INTO t1 () values ()";
INSERT INTO t1 () values ();
EXECUTE stmt;
 
# Cleanup
DROP TABLE t1;
DROP SEQUENCE s;

10.3 debug f3f23b5c

#3  <signal handler called>
#4  0x000055deeb8e246e in Item_func_nextval::val_int (this=0x7f2a00075d70) at /data/src/10.3/sql/item_func.cc:6791
#5  0x000055deeb8748d2 in Item::save_int_in_field (this=0x7f2a00075d70, field=0x7f2a00075ad0, no_conversions=false) at /data/src/10.3/sql/item.cc:6906
#6  0x000055deeb7289ca in Type_handler_int_result::Item_save_in_field (this=0x55deecbc8960 <type_handler_longlong>, item=0x7f2a00075d70, field=0x7f2a00075ad0, no_conversions=false) at /data/src/10.3/sql/sql_type.cc:2585
#7  0x000055deeb87497d in Item::save_in_field (this=0x7f2a00075d70, field=0x7f2a00075ad0, no_conversions=false) at /data/src/10.3/sql/item.cc:6916
#8  0x000055deeb65831e in TABLE::update_default_fields (this=0x7f2a00074e60, ignore_errors=false) at /data/src/10.3/sql/table.cc:8047
#9  0x000055deeb4a24e1 in fill_record (thd=0x7f2a00000af0, table_arg=0x7f2a00074e60, fields=..., values=..., ignore_errors=false, update=false) at /data/src/10.3/sql/sql_base.cc:8403
#10 0x000055deeb4a29ee in fill_record_n_invoke_before_triggers (thd=0x7f2a00000af0, table=0x7f2a00074e60, fields=..., values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /data/src/10.3/sql/sql_base.cc:8538
#11 0x000055deeb4e8047 in mysql_insert (thd=0x7f2a00000af0, table_list=0x7f2a0007fa80, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /data/src/10.3/sql/sql_insert.cc:968
#12 0x000055deeb52c358 in mysql_execute_command (thd=0x7f2a00000af0) at /data/src/10.3/sql/sql_parse.cc:4446
#13 0x000055deeb557444 in Prepared_statement::execute (this=0x7f2a000741a0, expanded_query=0x7f2a11b82c70, open_cursor=false) at /data/src/10.3/sql/sql_prepare.cc:4812
#14 0x000055deeb5556ae in Prepared_statement::execute_loop (this=0x7f2a000741a0, expanded_query=0x7f2a11b82c70, open_cursor=false, packet=0x0, packet_end=0x0) at /data/src/10.3/sql/sql_prepare.cc:4240
#15 0x000055deeb55318e in mysql_sql_stmt_execute (thd=0x7f2a00000af0) at /data/src/10.3/sql/sql_prepare.cc:3348
#16 0x000055deeb52a330 in mysql_execute_command (thd=0x7f2a00000af0) at /data/src/10.3/sql/sql_parse.cc:3828
#17 0x000055deeb537ea3 in mysql_parse (thd=0x7f2a00000af0, rawbuf=0x7f2a00012818 "EXECUTE stmt", length=12, parser_state=0x7f2a11b835e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7810
#18 0x000055deeb5246ea in dispatch_command (command=COM_QUERY, thd=0x7f2a00000af0, packet=0x7f2a001236f1 "EXECUTE stmt", packet_length=12, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1848
#19 0x000055deeb523002 in do_command (thd=0x7f2a00000af0) at /data/src/10.3/sql/sql_parse.cc:1393
#20 0x000055deeb69c4d7 in do_handle_one_connection (connect=0x55deee017d40) at /data/src/10.3/sql/sql_connect.cc:1403
#21 0x000055deeb69c239 in handle_one_connection (arg=0x55deee017d40) at /data/src/10.3/sql/sql_connect.cc:1308
#22 0x000055deec0530e8 in pfs_spawn_thread (arg=0x55deedfc3430) at /data/src/10.3/storage/perfschema/pfs.cc:1869
#23 0x00007f2a1990d4a4 in start_thread (arg=0x7f2a11b84700) at pthread_create.c:456
#24 0x00007f2a17a41d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible on 10.3-10.5, at least with InnoDB and MyISAM.

With the provided test case it does not crashes for me on non-debug builds, but they are definitely affected – more complicated tests fails on release builds as well, and ASAN fails with use-after-poison with debug and non-debug alike:

10.3 asan f3f23b5c

==7606==ERROR: AddressSanitizer: use-after-poison on address 0x62b000000cd0 at pc 0x55d0d0008e00 bp 0x7fc4609e0ae0 sp 0x7fc4609e0ad8
READ of size 8 at 0x62b000000cd0 thread T5
    #0 0x55d0d0008dff in Item_func_nextval::update_table() /data/src/10.3/sql/item_func.h:3153
    #1 0x55d0cfffdd6e in Item_func_nextval::val_int() /data/src/10.3/sql/item_func.cc:6790
    #2 0x55d0cfefb658 in Item::save_int_in_field(Field*, bool) /data/src/10.3/sql/item.cc:6906
    #3 0x55d0cfc244bf in Type_handler_int_result::Item_save_in_field(Item*, Field*, bool) const /data/src/10.3/sql/sql_type.cc:2585
    #4 0x55d0cfefb834 in Item::save_in_field(Field*, bool) /data/src/10.3/sql/item.cc:6916
    #5 0x55d0cfa608d5 in TABLE::update_default_fields(bool) /data/src/10.3/sql/table.cc:8047
    #6 0x55d0cf6566c0 in fill_record(THD*, TABLE*, List<Item>&, List<Item>&, bool, bool) /data/src/10.3/sql/sql_base.cc:8403
    #7 0x55d0cf657323 in fill_record_n_invoke_before_triggers(THD*, TABLE*, List<Item>&, List<Item>&, bool, trg_event_type) /data/src/10.3/sql/sql_base.cc:8538
    #8 0x55d0cf6f5b10 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /data/src/10.3/sql/sql_insert.cc:968
    #9 0x55d0cf7915dd in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4446
    #10 0x55d0cf7f0227 in Prepared_statement::execute(String*, bool) /data/src/10.3/sql/sql_prepare.cc:4812
    #11 0x55d0cf7eb89a in Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*) /data/src/10.3/sql/sql_prepare.cc:4240
    #12 0x55d0cf7e6271 in mysql_sql_stmt_execute(THD*) /data/src/10.3/sql/sql_prepare.cc:3348
    #13 0x55d0cf78e2b4 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:3828
    #14 0x55d0cf7a7d50 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7810
    #15 0x55d0cf782712 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1848
    #16 0x55d0cf77f5be in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1393
    #17 0x55d0cfafa16d in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
    #18 0x55d0cfaf9b34 in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
    #19 0x55d0d0f71853 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
    #20 0x7fc46c8364a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
    #21 0x7fc46a96ad0e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe8d0e)
 
0x62b000000cd0 is located 2768 bytes inside of 24716-byte region [0x62b000000200,0x62b00000628c)
allocated by thread T5 here:
    #0 0x7fc46cb0dd28 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1d28)
    #1 0x55d0d10a2112 in sf_malloc /data/src/10.3/mysys/safemalloc.c:118
    #2 0x55d0d1073cfa in my_malloc /data/src/10.3/mysys/my_malloc.c:101
    #3 0x55d0d10536ef in reset_root_defaults /data/src/10.3/mysys/my_alloc.c:151
    #4 0x55d0cf69434f in THD::init_for_queries() /data/src/10.3/sql/sql_class.cc:1343
    #5 0x55d0cfaf94d9 in prepare_new_connection_state(THD*) /data/src/10.3/sql/sql_connect.cc:1239
    #6 0x55d0cfaf9b7a in thd_prepare_connection(THD*) /data/src/10.3/sql/sql_connect.cc:1323
    #7 0x55d0cfafa120 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1393
    #8 0x55d0cfaf9b34 in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
    #9 0x55d0d0f71853 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
    #10 0x7fc46c8364a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
 
Thread T5 created by T0 here:
    #0 0x7fc46ca7cf59 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.3+0x30f59)
    #1 0x55d0d0f71c8f in spawn_thread_v1 /data/src/10.3/storage/perfschema/pfs.cc:1919
    #2 0x55d0cf4ead40 in inline_mysql_thread_create /data/src/10.3/include/mysql/psi/mysql_thread.h:1275
    #3 0x55d0cf50022f in create_thread_to_handle_connection(CONNECT*) /data/src/10.3/sql/mysqld.cc:6607
    #4 0x55d0cf500912 in create_new_thread /data/src/10.3/sql/mysqld.cc:6677
    #5 0x55d0cf50192a in handle_connections_sockets() /data/src/10.3/sql/mysqld.cc:6952
    #6 0x55d0cf4ff6ff in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:6229
    #7 0x55d0cf4e945f in main /data/src/10.3/sql/main.cc:25
    #8 0x7fc46a8a22e0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202e0)
 
SUMMARY: AddressSanitizer: use-after-poison /data/src/10.3/sql/item_func.h:3153 in Item_func_nextval::update_table()
Shadow bytes around the buggy address:
  0x0c567fff8140: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff8150: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff8160: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff8170: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff8180: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
=>0x0c567fff8190: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]f7 f7 f7 f7 f7
  0x0c567fff81a0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff81b0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff81c0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff81d0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c567fff81e0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Heap right redzone:      fb
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack partial redzone:   f4
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==7606==ABORTING

Comment by Alice Sherepa [ 2021-07-15 ]

./mtr sql_sequence.default  --view

10.3 3fbe30024ff0b4e3f6e630

Version: '10.3.31-MariaDB-debug-log'  
=================================================================
==55183==ERROR: AddressSanitizer: use-after-poison on address 0x62b000040970 at pc 0x55e30d92beec bp 0x7f2472880380 sp 0x7f2472880378
READ of size 8 at 0x62b000040970 thread T5
    #0 0x55e30d92beeb in Item_func_nextval::update_table() /10.3/sql/item_func.h:3153
    #1 0x55e30d920440 in Item_func_nextval::val_int() /10.3/sql/item_func.cc:6792
    #2 0x55e30d811138 in Item::save_int_in_field(Field*, bool) /10.3/sql/item.cc:6888
    #3 0x55e30d51ff09 in Type_handler_int_result::Item_save_in_field(Item*, Field*, bool) const /10.3/sql/sql_type.cc:2592
    #4 0x55e30d811316 in Item::save_in_field(Field*, bool) /10.3/sql/item.cc:6898
    #5 0x55e30d6e0047 in Field::set_default() /10.3/sql/field.cc:2420
    #6 0x55e30d829fef in Item_default_value::calculate() /10.3/sql/item.cc:9428
    #7 0x55e30d82a1db in Item_default_value::send(Protocol*, st_value*) /10.3/sql/item.cc:9464
    #8 0x55e30d81cfbc in Item_ref::send(Protocol*, st_value*) /10.3/sql/item.cc:8273
    #9 0x55e30d8267ae in Item_direct_view_ref::send(Protocol*, st_value*) /10.3/sql/item.cc:8999
    #10 0x55e30cd32b0d in Protocol::send_result_set_row(List<Item>*) /10.3/sql/protocol.cc:999
    #11 0x55e30cedc74e in select_send::send_data(List<Item>&) /10.3/sql/sql_class.cc:2999
    #12 0x55e30d131a4d in end_send /10.3/sql/sql_select.cc:20994
    #13 0x55e30d129182 in evaluate_join_record /10.3/sql/sql_select.cc:20034
    #14 0x55e30d1279aa in sub_select(JOIN*, st_join_table*, bool) /10.3/sql/sql_select.cc:19814
    #15 0x55e30d1256b3 in do_select /10.3/sql/sql_select.cc:19354
    #16 0x55e30d0b58b3 in JOIN::exec_inner() /10.3/sql/sql_select.cc:4138
    #17 0x55e30d0b328b in JOIN::exec() /10.3/sql/sql_select.cc:3932
    #18 0x55e30d0b6bc1 in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /10.3/sql/sql_select.cc:4340
    #19 0x55e30d08d4a5 in handle_select(THD*, LEX*, select_result*, unsigned long) /10.3/sql/sql_select.cc:372
    #20 0x55e30cff8e27 in execute_sqlcom_select /10.3/sql/sql_parse.cc:6339
    #21 0x55e30cfe6e26 in mysql_execute_command(THD*) /10.3/sql/sql_parse.cc:3870
    #22 0x55e30d002f16 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /10.3/sql/sql_parse.cc:7870
    #23 0x55e30cfd96ad in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /10.3/sql/sql_parse.cc:1852
    #24 0x55e30cfd5df4 in do_command(THD*) /10.3/sql/sql_parse.cc:1398
    #25 0x55e30d3cb361 in do_handle_one_connection(CONNECT*) /10.3/sql/sql_connect.cc:1403
    #26 0x55e30d3cac19 in handle_one_connection /10.3/sql/sql_connect.cc:1308
    #27 0x55e30eb48eb0 in pfs_spawn_thread /10.3/storage/perfschema/pfs.cc:1869
    #28 0x7f247cbd5fa2 in start_thread /build/glibc-vjB4T1/glibc-2.28/nptl/pthread_create.c:486
    #29 0x7f247cb064ce in clone (/lib/x86_64-linux-gnu/libc.so.6+0xf94ce)
 
0x62b000040970 is located 6000 bytes inside of 24716-byte region [0x62b00003f200,0x62b00004528c)
allocated by thread T6 here:
    #0 0x7f247d285330 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.5+0xe9330)
    #1 0x55e30ed5d126 in sf_malloc /10.3/mysys/safemalloc.c:118
    #2 0x55e30ed2c684 in my_malloc /10.3/mysys/my_malloc.c:101
    #3 0x55e30ed08c0a in reset_root_defaults /10.3/mysys/my_alloc.c:152
    #4 0x55e30cecfd89 in THD::init_for_queries() /10.3/sql/sql_class.cc:1343
    #5 0x55e30d3ca552 in prepare_new_connection_state(THD*) /10.3/sql/sql_connect.cc:1239
    #6 0x55e30d3cac5f in thd_prepare_connection(THD*) /10.3/sql/sql_connect.cc:1323
    #7 0x55e30d3cb28c in do_handle_one_connection(CONNECT*) /10.3/sql/sql_connect.cc:1393
    #8 0x55e30d3cac19 in handle_one_connection /10.3/sql/sql_connect.cc:1308
    #9 0x55e30eb48eb0 in pfs_spawn_thread /10.3/storage/perfschema/pfs.cc:1869
    #10 0x7f247cbd5fa2 in start_thread /build/glibc-vjB4T1/glibc-2.28/nptl/pthread_create.c:486
 
Thread T5 created by T0 here:
    #0 0x7f247d1ecdb0 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.5+0x50db0)
    #1 0x55e30eb492ec in spawn_thread_v1 /10.3/storage/perfschema/pfs.cc:1919
    #2 0x55e30cce76f4 in inline_mysql_thread_create /10.3/include/mysql/psi/mysql_thread.h:1275
    #3 0x55e30cd0103b in create_thread_to_handle_connection(CONNECT*) /10.3/sql/mysqld.cc:6664
    #4 0x55e30cd01790 in create_new_thread /10.3/sql/mysqld.cc:6734
    #5 0x55e30cd02911 in handle_connections_sockets() /10.3/sql/mysqld.cc:6992
    #6 0x55e30cd003af in mysqld_main(int, char**) /10.3/sql/mysqld.cc:6286
    #7 0x55e30cce5df4 in main /10.3/sql/main.cc:25
    #8 0x7f247ca3109a in __libc_start_main ../csu/libc-start.c:308
 
Thread T6 created by T0 here:
    #0 0x7f247d1ecdb0 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.5+0x50db0)
    #1 0x55e30eb492ec in spawn_thread_v1 /10.3/storage/perfschema/pfs.cc:1919
    #2 0x55e30cce76f4 in inline_mysql_thread_create /10.3/include/mysql/psi/mysql_thread.h:1275
    #3 0x55e30cd0103b in create_thread_to_handle_connection(CONNECT*) /10.3/sql/mysqld.cc:6664
    #4 0x55e30cd01790 in create_new_thread /10.3/sql/mysqld.cc:6734
    #5 0x55e30cd02911 in handle_connections_sockets() /10.3/sql/mysqld.cc:6992
    #6 0x55e30cd003af in mysqld_main(int, char**) /10.3/sql/mysqld.cc:6286
    #7 0x55e30cce5df4 in main /10.3/sql/main.cc:25
    #8 0x7f247ca3109a in __libc_start_main ../csu/libc-start.c:308
 
SUMMARY: AddressSanitizer: use-after-poison /10.3/sql/item_func.h:3153 in Item_func_nextval::update_table()
Shadow bytes around the buggy address:
  0x0c56800000d0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c56800000e0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c56800000f0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000100: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000110: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
=>0x0c5680000120: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]f7
  0x0c5680000130: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000140: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000150: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000160: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
  0x0c5680000170: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==55183==ABORTING
----------SERVER LOG END-------------

Comment by Michael Widenius [ 2021-08-26 ]

The bug was exposed if one used DEFAULT NEXT_VALUE() for a table and the table was used by both a prepared statement and a normal statement.
The bug could cause a crash as it already freed memory was accessed.
The fix was to update the pointer to the freed memory for this case.

Comment by Karsten Budde [ 2021-08-26 ]

How can I update die pointer to the freed memory?

Comment by Roel Van de Paar [ 2021-08-28 ]

KB_Heinze This will require a patch in the code. The ticket is already marked as fixed and a fix for this bug will be included in an upcoming release of the server.

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