[MDEV-22661] Assertion `time_type == MYSQL_TIMESTAMP_DATETIME' failed in Datetime::is_valid_datetime_slow Created: 2020-05-22  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Data Manipulation - Insert
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-29726 Assertion failure upon DELETE HISTORY... Open

 Description    

USE test;
 
CREATE TABLE t(c INT DEFAULT (1 LIKE (NOW() BETWEEN '' AND '')));
 
INSERT DELAYED INTO t VALUES(1);

Leads to:

10.4.13 edc3899d9781e98b4328931884527913ebffb11f

 
mysqld: /test/10.4_dbg/sql/sql_type.h:1996: bool Datetime::is_valid_datetime_slow() const: Assertion `time_type == MYSQL_TIMESTAMP_DATETIME' failed.

10.4.13 edc3899d9781e98b4328931884527913ebffb11f

 
Core was generated by `/test/MD110420-mariadb-10.4.13-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x14df6b6f9700 (LWP 87237))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055c37dcef36b in my_write_core (sig=sig@entry=6) at /test/10.4_dbg/mysys/stacktrace.c:481
 
#2  0x000055c37d47ca62 in handle_fatal_signal (sig=6) at /test/10.4_dbg/sql/signal_handler.cc:343
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x000014df69c06801 in __GI_abort () at abort.c:79
 
#6  0x000014df69bf639a in __assert_fail_base (fmt=0x14df69d7d7d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55c37dd9d090 "time_type == MYSQL_TIMESTAMP_DATETIME", file=file@entry=0x55c37dd9cf3f "/test/10.4_dbg/sql/sql_type.h", line=line@entry=1996, function=function@entry=0x55c37dd9d420 <Datetime::is_valid_datetime_slow() const::__PRETTY_FUNCTION__> "bool Datetime::is_valid_datetime_slow() const") at assert.c:92
 
#7  0x000014df69bf6412 in __GI___assert_fail (assertion=assertion@entry=0x55c37dd9d090 "time_type == MYSQL_TIMESTAMP_DATETIME", file=file@entry=0x55c37dd9cf3f "/test/10.4_dbg/sql/sql_type.h", line=line@entry=1996, function=function@entry=0x55c37dd9d420 <Datetime::is_valid_datetime_slow() const::__PRETTY_FUNCTION__> "bool Datetime::is_valid_datetime_slow() const") at assert.c:101
 
#8  0x000055c37d0daba0 in Datetime::is_valid_datetime_slow (this=0x14df6b6f59b0) at /test/10.4_dbg/sql/sql_type.h:1996
 
#9  Datetime::is_valid_value_slow (this=0x14df6b6f59b0) at /test/10.4_dbg/sql/sql_type.h:1992
 
#10 Datetime::Datetime (fuzzydate=..., item=0x14df448408e0, thd=0x14df444e4090, this=0x14df6b6f59b0) at /test/10.4_dbg/sql/sql_type.h:2064
 
#11 Item::val_datetime_packed (this=0x14df448408e0, thd=0x14df444e4090) at /test/10.4_dbg/sql/item.h:1758
 
#12 0x000055c37d4cfa01 in Item_func_between::val_int_cmp_datetime (this=0x14df44840c98) at /test/10.4_dbg/sql/item_cmpfunc.cc:2168
 
#13 0x000055c37d37c408 in Type_handler_temporal_with_date::Item_func_between_val_int (this=<optimized out>, func=<optimized out>) at /test/10.4_dbg/sql/sql_type.cc:5013
 
#14 0x000055c37d61507d in Item_func_between::val_int (this=0x14df44840c98) at /test/10.4_dbg/sql/item_cmpfunc.h:913
 
#15 0x000055c37d5017a1 in Item_int_func::val_str (this=0x14df44840c98, str=0x14df44874db8) at /test/10.4_dbg/sql/item_func.cc:752
 
#16 0x000055c37d4d5536 in Item_func_like::fix_fields (this=0x14df44874c88, thd=0x14df444e4090, ref=<optimized out>) at /test/10.4_dbg/sql/item_cmpfunc.cc:5637
 
#17 0x000055c37d2b0f9b in fix_vcol_expr (thd=thd@entry=0x14df444e4090, vcol=vcol@entry=0x14df44840a00) at /test/10.4_dbg/sql/table.cc:3234
 
#18 0x000055c37d2b1926 in fix_and_check_vcol_expr (vcol=0x14df44840a00, table=0x14df44894070, thd=0x14df444e4090) at /test/10.4_dbg/sql/table.cc:3319
 
#19 unpack_vcol_info_from_frm (thd=thd@entry=0x14df444e4090, mem_root=mem_root@entry=0x14df44894d40, table=table@entry=0x14df44894070, expr_str=expr_str@entry=0x14df6b6f7da0, vcol_ptr=0x14df44840778, error_reported=error_reported@entry=0x14df6b6f8157) at /test/10.4_dbg/sql/table.cc:3446
 
#20 0x000055c37d2b9bb3 in parse_vcol_defs (thd=thd@entry=0x14df444e4090, mem_root=mem_root@entry=0x14df44894d40, table=table@entry=0x14df44894070, error_reported=error_reported@entry=0x14df6b6f8157, mode=mode@entry=VCOL_INIT_DEPENDENCY_FAILURE_IS_WARNING) at /test/10.4_dbg/sql/table.cc:1179
 
#21 0x000055c37d2c257a in open_table_from_share (thd=thd@entry=0x14df444e4090, share=share@entry=0x14df44825688, alias=alias@entry=0x14df444ea830, db_stat=db_stat@entry=33, prgflag=prgflag@entry=8, ha_open_flags=<optimized out>, outparam=<optimized out>, is_create_table=<optimized out>, partitions_to_open=<optimized out>) at /test/10.4_dbg/sql/table.cc:3816
 
#22 0x000055c37d1427fe in open_table (thd=thd@entry=0x14df444e4090, table_list=table_list@entry=0x14df444ea7e8, ot_ctx=ot_ctx@entry=0x14df6b6f8b20) at /test/10.4_dbg/sql/sql_base.cc:2082
 
#23 0x000055c37d146cb6 in open_and_process_table (ot_ctx=0x14df6b6f8b20, has_prelocking_list=false, prelocking_strategy=0x14df6b6f8ca8, flags=65537, counter=0x14df6b6f8bbc, tables=0x14df444ea7e8, thd=0x14df444e4090) at /test/10.4_dbg/sql/sql_base.cc:3850
 
#24 open_tables (thd=thd@entry=0x14df444e4090, options=..., start=start@entry=0x14df6b6f8ba8, counter=counter@entry=0x14df6b6f8bbc, flags=flags@entry=65537, prelocking_strategy=prelocking_strategy@entry=0x14df6b6f8ca8) at /test/10.4_dbg/sql/sql_base.cc:4322
 
#25 0x000055c37d147f89 in open_and_lock_tables (thd=thd@entry=0x14df444e4090, options=..., tables=<optimized out>, tables@entry=0x14df444ea7e8, derived=derived@entry=false, flags=flags@entry=65537, prelocking_strategy=prelocking_strategy@entry=0x14df6b6f8ca8) at /test/10.4_dbg/sql/sql_base.cc:5217
 
#26 0x000055c37d148121 in open_and_lock_tables (prelocking_strategy=0x14df6b6f8ca8, flags=65537, derived=false, tables=0x14df444ea7e8, thd=0x14df444e4090) at /test/10.4_dbg/sql/sql_base.h:271
 
#27 open_n_lock_single_table (thd=thd@entry=0x14df444e4090, table_l=table_l@entry=0x14df444ea7e8, lock_type=lock_type@entry=TL_WRITE_DELAYED, flags=flags@entry=65537, prelocking_strategy=prelocking_strategy@entry=0x14df6b6f8ca8) at /test/10.4_dbg/sql/sql_base.cc:5060
 
#28 0x000055c37d187275 in Delayed_insert::open_and_lock_table (this=this@entry=0x14df444e4070) at /test/10.4_dbg/sql/sql_insert.cc:2970
 
#29 0x000055c37d188aa6 in handle_delayed_insert (arg=0x14df444e4070) at /test/10.4_dbg/sql/sql_insert.cc:3073
 
#30 0x000014df6a8e96db in start_thread (arg=0x14df6b6f9700) at pthread_create.c:463
 
#31 0x000014df69ce788f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.23 (dbg), 10.4.13 (dbg), 10.5.2 (dbg), 10.5.3 (dbg), 10.5.6 (dbg) @ 1c587481966abc7a9ad5309d0a91ca920f7a5657

Bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (opt), 10.2.32 (dbg), 10.2.32 (opt), 10.3.23 (opt), 10.4.13 (opt), 10.5.2 (opt), 10.5.3 (opt), 10.5.4 (dbg), 10.5.4 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Roel Van de Paar [ 2020-09-26 ]

Different testcase with different stack, same assert

SET SQL_MODE='';
 
CREATE TABLE t (a INT AS (b + 1), b INT, row_start BIGINT UNSIGNED AS ROW START INVISIBLE, row_end BIGINT UNSIGNED AS ROW END INVISIBLE, PERIOD FOR system_time (row_start, row_end)) WITH SYSTEM VERSIONING;
 
INSERT INTO test.t (a) VALUES (poINT (1,1));
 
SELECT * FROM t FOR system_time FROM '0-0-0' TO CURRENT_TIMESTAMP(6);

Leads to:

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

 
mysqld: /test/10.5_dbg/sql/sql_type.h:2249: bool Datetime::is_valid_datetime_slow() const: Assertion `time_type == MYSQL_TIMESTAMP_DATETIME' failed.

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

 
Core was generated by `/test/MD150920-mariadb-10.5.6-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x150e6765a700 (LWP 2966268))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055785bb9085a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
 
#2  0x000055785b3573a9 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x0000150e658f08b1 in __GI_abort () at abort.c:79
 
#6  0x0000150e658e042a in __assert_fail_base (fmt=0x150e65a67a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55785bce9c90 "time_type == MYSQL_TIMESTAMP_DATETIME", file=file@entry=0x55785bce9b3f "/test/10.5_dbg/sql/sql_type.h", line=line@entry=2249, function=function@entry=0x55785bd37040 <_ZZNK8Datetime22is_valid_datetime_slowEvE19__PRETTY_FUNCTION__> "bool Datetime::is_valid_datetime_slow() const") at assert.c:92
 
#7  0x0000150e658e04a2 in __GI___assert_fail (assertion=assertion@entry=0x55785bce9c90 "time_type == MYSQL_TIMESTAMP_DATETIME", file=file@entry=0x55785bce9b3f "/test/10.5_dbg/sql/sql_type.h", line=line@entry=2249, function=function@entry=0x55785bd37040 <_ZZNK8Datetime22is_valid_datetime_slowEvE19__PRETTY_FUNCTION__> "bool Datetime::is_valid_datetime_slow() const") at assert.c:101
 
#8  0x000055785b1bb17c in Datetime::is_valid_datetime_slow (this=0x150e676572c0) at /test/10.5_dbg/sql/sql_type.h:2249
 
#9  Datetime::Datetime (from=0x150e67657b70, this=0x150e676572c0) at /test/10.5_dbg/sql/sql_type.h:2401
 
#10 TR_table::query (this=this@entry=0x150e67657440, commit_time=@0x150e67657b70: {year = 0, month = 0, day = 0, hour = 0, minute = 0, second = 0, second_part = 0, neg = 0 '\000', time_type = MYSQL_TIMESTAMP_DATE}, backwards=backwards@entry=true) at /test/10.5_dbg/sql/table.cc:9603
 
#11 0x000055785b2aa93b in Item_func_trt_id::get_by_commit_ts (this=this@entry=0x150e43076140, commit_ts=@0x150e67657b70: {year = 0, month = 0, day = 0, hour = 0, minute = 0, second = 0, second_part = 0, neg = 0 '\000', time_type = MYSQL_TIMESTAMP_DATE}, backwards=true) at /test/10.5_dbg/sql/item_vers.cc:120
 
#12 0x000055785b2aab3e in Item_func_trt_id::val_int (this=0x150e43076140) at /test/10.5_dbg/sql/item_vers.cc:154
 
#13 0x000055785afb5bad in Item::val_int_result (this=<optimized out>) at /test/10.5_dbg/sql/item.h:1565
 
#14 0x000055785b376f04 in Item_cache_int::cache_value (this=0x150e43078b90) at /test/10.5_dbg/sql/item.cc:9840
 
#15 0x000055785b376fab in Item_cache::has_value (this=0x150e43078b90) at /test/10.5_dbg/sql/item.h:6801
 
#16 Item_cache_int::val_int (this=0x150e43078b90) at /test/10.5_dbg/sql/item.cc:9873
 
#17 0x000055785b2aa08c in Item::val_uint (this=<optimized out>) at /test/10.5_dbg/sql/item.h:1288
 
#18 Item_func_trt_trx_sees::val_int (this=0x150e430763b8) at /test/10.5_dbg/sql/item_vers.cc:174
 
#19 0x000055785b27a0e0 in Type_handler_int_result::Item_val_bool (this=<optimized out>, item=<optimized out>) at /test/10.5_dbg/sql/sql_type.cc:5019
 
#20 0x000055785afb5b30 in Item::val_bool (this=0x150e430763b8) at /test/10.5_dbg/sql/item.h:1483
 
#21 0x000055785b3a33fb in Item_cond_and::val_int (this=0x150e43078e20) at /test/10.5_dbg/sql/item_cmpfunc.cc:5427
 
#22 0x000055785b0e3c9f in evaluate_join_record (join=join@entry=0x150e43075920, join_tab=join_tab@entry=0x150e43078250, error=error@entry=0) at /test/10.5_dbg/sql/sql_select.cc:20735
 
#23 0x000055785b0eb20b in sub_select (join=0x150e43075920, join_tab=0x150e43078250, end_of_records=<optimized out>) at /test/10.5_dbg/sql/sql_select.cc:20637
 
#24 0x000055785b125476 in do_select (procedure=0x0, join=0x150e43075920) at /test/10.5_dbg/sql/sql_select.cc:20171
 
#25 JOIN::exec_inner (this=this@entry=0x150e43075920) at /test/10.5_dbg/sql/sql_select.cc:4455
 
#26 0x000055785b125a91 in JOIN::exec (this=this@entry=0x150e43075920) at /test/10.5_dbg/sql/sql_select.cc:4236
 
#27 0x000055785b123d8d in mysql_select (thd=thd@entry=0x150e43015088, tables=<optimized out>, fields=@0x150e430742e0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x150e43074740, last = 0x150e43076c00, elements = 2}, <No data fields>}, conds=0x0, og_num=0, order=<optimized out>, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x150e430758f8, unit=0x150e43019220, select_lex=0x150e43074190) at /test/10.5_dbg/sql/sql_select.cc:4663
 
#28 0x000055785b1240bc in handle_select (thd=thd@entry=0x150e43015088, lex=lex@entry=0x150e43019158, result=result@entry=0x150e430758f8, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.5_dbg/sql/sql_select.cc:417
 
#29 0x000055785b0ab348 in execute_sqlcom_select (thd=thd@entry=0x150e43015088, all_tables=0x150e43074928) at /test/10.5_dbg/sql/sql_parse.cc:6210
 
#30 0x000055785b0a441c in mysql_execute_command (thd=thd@entry=0x150e43015088) at /test/10.5_dbg/sql/sql_parse.cc:3932
 
#31 0x000055785b0b1324 in mysql_parse (thd=thd@entry=0x150e43015088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x150e67659350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
 
#32 0x000055785b09dd54 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x150e43015088, packet=packet@entry=0x150e43067089 "", packet_length=packet_length@entry=68, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1867
 
#33 0x000055785b09c53e in do_command (thd=0x150e43015088) at /test/10.5_dbg/sql/sql_parse.cc:1348
 
#34 0x000055785b1fb893 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x150e464d4808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
 
#35 0x000055785b1fbfb7 in handle_one_connection (arg=arg@entry=0x150e464d4808) at /test/10.5_dbg/sql/sql_connect.cc:1312
 
#36 0x000055785b6665c2 in pfs_spawn_thread (arg=0x150e64446508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#37 0x0000150e665d36db in start_thread (arg=0x150e6765a700) at pthread_create.c:463
 
#38 0x0000150e659d1a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.15 (dbg), 10.5.6 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.47 (dbg), 10.1.47 (opt), 10.2.34 (dbg), 10.2.34 (opt), 10.3.25 (dbg), 10.3.25 (opt), 10.4.15 (opt), 10.5.6 (opt), 10.6.0 (dbg), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.49 (dbg), 5.6.49 (opt), 5.7.31 (dbg), 5.7.31 (opt), 8.0.21 (dbg), 8.0.21 (opt)

sanja Please let me know if you consider this a different bug altogether.

Comment by Roel Van de Paar [ 2020-09-26 ]

This bug is seen somewhat frequently in test runs.

Comment by Weijun Huang [ 2023-03-12 ]

This bug can be observed in sql_type.h:383:24. After date_to_datetime, time_type does not change to MYSQL_TIMESTAMP_DATETIME, but a negative number. I think this is caused by INSERT DELAYED

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