[MDEV-13435] Crash when selecting virtual columns generated using JSON functions Created: 2017-08-03  Updated: 2017-08-14  Resolved: 2017-08-14

Status: Closed
Project: MariaDB Server
Component/s: JSON, Virtual Columns
Affects Version/s: 10.2.6, 10.2.7
Fix Version/s: 10.2.8

Type: Bug Priority: Major
Reporter: Robert Humphries Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None
Environment:

Operating System: CentOS Linux release 7.3.1611 (Core)
Originally found on an Amazon EC2 Instance, with Plesk as the control panel for the server. MariaDB had been upgraded twice (from the CentOS's own version to 10.1 and then to 10.2)
Replicated on an internal XenServer 7.1 instance,with a clean install of CentOS (basic install), and MariaDB 10.2 installed with no upgrade process.

Attachments: File bugReportDump.sql     Text File errorLogAfterInsertThenSelect.txt     Text File errorLogAfterUpdateThenFullSelect.txt     Text File errorLogAfterUpdateThenPartialSelect.txt     Text File errorLogAfterUpdateThenPartialSelectAfterInactivity.txt    

 Description   

I have discovered an issue which causes the server to crash and restart, when it is trying to calculate (or after it has calculated) a virtual column. I have been able to reliably reproduce this with the table structure below, if I insert a record, update a record (regardless of if the update affects the field the virtual column is calculated on or not) or delete a record, then the next time I do a select that includes one of the virtual columns (including select *), MariaDB will crash. The reason I am listing this with the summary saying "non-cached" and I earlier said that it crashes after calculating the virtual column is that once the server has restarted, if you rerun the select, it works fine - with the correct calculated column.

The table in question is called 'supplierSendingTimes'. There are two virtual columns, looking at a JSON string to select from it two times (a start time and an end time) - with the column definitions varying only in that they select the key "start" or "end". The column definition is (the full table def is in bugReportDump.sql:

`currentStartTime` time GENERATED ALWAYS AS (coalesce(cast(json_value(json_extract(`jsonRuleString`,concat('$.singleDates."',curdate(),'"')),'$.start') as time),cast(json_value(json_extract(`jsonRuleString`,concat('$.singleDay."',dayname(curdate()),'"')),'$.start') as time),cast(json_value(json_extract(`jsonRuleString`,'$.default'),'$.start') as time))) VIRTUAL,

The stack trace appears to be different, depending on if you are inserting or updating; and if updating, if you are doing a select * or select <columns>. I haven't check the error logs, but it might also be different on delete, if it would be useful for me to check, please let me know.

Hopefully this is enough information, but if I can provide further information, please let me know.

 Comments   
Comment by Alice Sherepa [ 2017-08-03 ]

Thanks for the report. Server crash, while attempting any action, that includes virtual column t (select or update, drop table or drop database)

Test case:

CREATE TABLE `t1` (
 
  `id` int  NOT NULL ,
 
  `js` varchar(1000) NOT NULL,
 
  `t` time AS (cast(json_value(json_extract(js,concat('$.singleDay."',dayname(curdate()),'"')),'$.start') as time)) virtual);
 
 
 
insert  into `t1`(id,js) values (0,'{\"default\":{\"start\":\"00:00:00\",\"end\":\"23:59:50\"}}');
 
 
select * from t1;

Stack traces from 10.2.8-MariaDB-debug

Thread pointer: 0x7f7248000b00
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7f72a5e35ec0 thread_stack 0x49000
 
/data/bld/10.2/bin/mysqld(my_print_stacktrace+0x38)[0x557133718b3c]
 
/data/bld/10.2/bin/mysqld(handle_fatal_signal+0x3a3)[0x557132fa803a]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f72be950390]
 
/data/bld/10.2/bin/mysqld(_ZN9Item_args9walk_argsEM4ItemFbPvEbS1_+0x56)[0x557132cdafd6]
 
/data/bld/10.2/bin/mysqld(_ZN16Item_func_or_sum4walkEM4ItemFbPvEbS1_+0x4f)[0x557132cdb403]
 
/data/bld/10.2/bin/mysqld(_ZN9Item_args9walk_argsEM4ItemFbPvEbS1_+0x7f)[0x557132cdafff]
 
/data/bld/10.2/bin/mysqld(_ZN16Item_func_or_sum4walkEM4ItemFbPvEbS1_+0x4f)[0x557132cdb403]
 
/data/bld/10.2/bin/mysqld(_ZN9Item_args9walk_argsEM4ItemFbPvEbS1_+0x7f)[0x557132cdafff]
 
mysys/stacktrace.c:267(my_print_stacktrace)[0x557132cdb403]
 
/data/bld/10.2/bin/mysqld(_ZN9Item_args9walk_argsEM4ItemFbPvEbS1_+0x7f)[0x557132cdafff]
 
/data/bld/10.2/bin/mysqld(_ZN16Item_func_or_sum4walkEM4ItemFbPvEbS1_+0x4f)[0x557132cdb403]
 
/data/bld/10.2/bin/mysqld(_ZN5TABLE16mark_virtual_colEP5Field+0xee)[0x557132e45638]
 
/data/bld/10.2/bin/mysqld(_Z13insert_fieldsP3THDP23Name_resolution_contextPKcS4_P13List_iteratorI4ItemEb+0x716)[0x557132cd6e54]
 
/data/bld/10.2/bin/mysqld(_Z10setup_wildP3THDP10TABLE_LISTR4ListI4ItemEPS5_j+0x298)[0x557132cd53d6]
 
/data/bld/10.2/bin/mysqld(_ZN4JOIN7prepareEP10TABLE_LISTjP4ItemjP8st_orderbS5_S3_S5_P13st_select_lexP18st_select_lex_unit+0x581)[0x557132d7b8eb]
 
/data/bld/10.2/bin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x241)[0x557132d85cc4]
 
/data/bld/10.2/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x15f)[0x557132d7a717]
 
/data/bld/10.2/bin/mysqld(+0x5b45a4)[0x557132d465a4]
 
sql/item.h:3874(Item_args::walk_args(bool (Item::*)(void*), bool, void*))[0x557132d3c2f4]
 
sql/item.h:4159(Item_func_or_sum::walk(bool (Item::*)(void*), bool, void*))[0x557132d49f1b]
 
sql/table.cc:6553(TABLE::mark_virtual_col(Field*))[0x557132d37cee]
 
sql/sql_parse.cc:7879(har*, unsigned int, Parser_state*, bool, bool))[0x557132d36628]
 
sql/sql_connect.cc:1354(do_handle_one_connection(CONNECT*))[0x557132e81fcc]
 
sql/sql_connect.cc:1261(handle_one_connection)[0x557132e81d4c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f72be9466ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f72bdddb3dd]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f7248010ea8): select * from t1
 
Connection ID (thread ID): 8
 
Status: NOT_KILLED
 
 
 
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on

core dump

 
 
Thread 1 (Thread 0x7fe656610700 (LWP 26998)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x000055be3b797c2e in my_write_core (sig=11) at /home/alice/git/10.2/mysys/stacktrace.c:477
 
#2  0x000055be3b0273d9 in handle_fatal_signal (sig=11) at /home/alice/git/10.2/sql/signal_handler.cc:299
 
#3  <signal handler called>
 
#4  __memmove_avx_unaligned () at ../sysdeps/x86_64/multiarch/memcpy-avx-unaligned.S:138
 
#5  0x000055be3ae73336 in String::copy (this=0x7fe644013568, str=...) at /home/alice/git/10.2/sql/sql_string.cc:177
 
#6  0x000055be3b0d12f8 in Item_func_concat::val_str (this=0x7fe64403e028, str=0x7fe644013568) at /home/alice/git/10.2/sql/item_strfunc.cc:606
 
#7  0x000055be3b206677 in Item_func_json_extract::val_str (this=0x7fe64403e278, str=0x7fe64403efa8) at /home/alice/git/10.2/sql/item_jsonfunc.cc:734
 
#8  0x000055be3acf7ba4 in Item::val_json (this=0x7fe64403e278, str=0x7fe64403efa8) at /home/alice/git/10.2/sql/item.h:1094
 
#9  0x000055be3b205860 in Item_func_json_value::val_str (this=0x7fe64403ea98, str=0x7fe65660d7a0) at /home/alice/git/10.2/sql/item_jsonfunc.cc:458
 
#10 0x000055be3b03f15d in Item::get_date (this=0x7fe64403ea98, ltime=0x7fe65660d8c0, fuzzydate=33554436) at /home/alice/git/10.2/sql/item.cc:1355
 
#11 0x000055be3b05b7c6 in Item::get_time (this=0x7fe64403ea98, ltime=0x7fe65660d8c0) at /home/alice/git/10.2/sql/item.h:1357
 
#12 0x000055be3b1188c3 in Item_func::get_arg0_time (this=0x7fe64403e530, ltime=0x7fe65660d8c0) at /home/alice/git/10.2/sql/item_func.h:165
 
#13 0x000055be3b116535 in Item_time_typecast::get_date (this=0x7fe64403e530, ltime=0x7fe65660d8c0, fuzzy_date=0) at /home/alice/git/10.2/sql/item_timefunc.cc:2556
 
#14 0x000055be3b03c684 in Item::save_date_in_field (this=0x7fe64403e530, field=0x7fe644038718) at /home/alice/git/10.2/sql/item.cc:435
 
#15 0x000055be3afdfb62 in Item_temporal_func::save_in_field (this=0x7fe64403e530, field=0x7fe644038718, no_conversions=false) at /home/alice/git/10.2/sql/item_timefunc.h:551
 
#16 0x000055be3aec6663 in TABLE::update_virtual_fields (this=0x7fe64403b440, h=0x7fe64403c048, update_mode=VCOL_UPDATE_FOR_READ) at /home/alice/git/10.2/sql/table.cc:7434
 
#17 0x000055be3b02dab4 in handler::ha_rnd_next (this=0x7fe64403c048, buf=0x7fe64403d1a8 "\377") at /home/alice/git/10.2/sql/handler.cc:2552
 
#18 0x000055be3b02f14b in handler::read_first_row (this=0x7fe64403c048, buf=0x7fe64403d1a8 "\377", primary_key=64) at /home/alice/git/10.2/sql/handler.cc:2782
 
#19 0x000055be3ae42417 in handler::ha_read_first_row (this=0x7fe64403c048, buf=0x7fe64403d1a8 "\377", primary_key=64) at /home/alice/git/10.2/sql/sql_class.h:5650
 
#20 0x000055be3ae2b619 in join_read_system (tab=0x7fe644013600) at /home/alice/git/10.2/sql/sql_select.cc:19086
 
#21 0x000055be3ae2b1d6 in join_read_const_table (thd=0x7fe644000b00, tab=0x7fe644013600, pos=0x7fe644013bb8) at /home/alice/git/10.2/sql/sql_select.cc:18982
 
#22 0x000055be3ae05f27 in make_join_statistics (join=0x7fe644012c60, tables_list=..., keyuse_array=0x7fe644012f50) at /home/alice/git/10.2/sql/sql_select.cc:4004
 
#23 0x000055be3adfd5a6 in JOIN::optimize_inner (this=0x7fe644012c60) at /home/alice/git/10.2/sql/sql_select.cc:1509
 
#24 0x000055be3adfbddd in JOIN::optimize (this=0x7fe644012c60) at /home/alice/git/10.2/sql/sql_select.cc:1085
 
#25 0x000055be3ae04ce6 in mysql_select (thd=0x7fe644000b00, tables=0x7fe644012550, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fe644012c40, unit=0x7fe6440045e8, select_lex=0x7fe644004d20) at /home/alice/git/10.2/sql/sql_select.cc:3664
 
#26 0x000055be3adf9717 in handle_select (thd=0x7fe644000b00, lex=0x7fe644004520, result=0x7fe644012c40, setup_tables_done_option=0) at /home/alice/git/10.2/sql/sql_select.cc:373
 
#27 0x000055be3adc55a4 in execute_sqlcom_select (thd=0x7fe644000b00, all_tables=0x7fe644012550) at /home/alice/git/10.2/sql/sql_parse.cc:6443
 
#28 0x000055be3adbb2f4 in mysql_execute_command (thd=0x7fe644000b00) at /home/alice/git/10.2/sql/sql_parse.cc:3458
 
#29 0x000055be3adc8f1b in mysql_parse (thd=0x7fe644000b00, rawbuf=0x7fe644012378 "select * from t1", length=16, parser_state=0x7fe65660f200, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:7879
 
#30 0x000055be3adb6cee in dispatch_command (command=COM_QUERY, thd=0x7fe644000b00, packet=0x7fe6441680b1 "select * from t1", packet_length=16, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:1817
 
#31 0x000055be3adb5628 in do_command (thd=0x7fe644000b00) at /home/alice/git/10.2/sql/sql_parse.cc:1362
 
#32 0x000055be3af00fcc in do_handle_one_connection (connect=0x55be3d83c420) at /home/alice/git/10.2/sql/sql_connect.cc:1354
 
#33 0x000055be3af00d4c in handle_one_connection (arg=0x55be3d83c420) at /home/alice/git/10.2/sql/sql_connect.cc:1260
 
#34 0x000055be3b2594b8 in pfs_spawn_thread (arg=0x55be3d8dedf0) at /home/alice/git/10.2/storage/perfschema/pfs.cc:1862
 
#35 0x00007fe65cf7a6ba in start_thread (arg=0x7fe656610700) at pthread_create.c:333
 
#36 0x00007fe65c40f3dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

crash after drop table t1;

Thread 1 (Thread 0x7ff8e2fc5700 (LWP 27113)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x0000561e605abc2e in my_write_core (sig=11) at /home/alice/git/10.2/mysys/stacktrace.c:477
 
#2  0x0000561e5fe3b3d9 in handle_fatal_signal (sig=11) at /home/alice/git/10.2/sql/signal_handler.cc:299
 
#3  <signal handler called>
 
#4  0x0000561e605b82f1 in sf_malloc_usable_size (ptr=0x8f8f8f8f8f8f8f8f, is_thread_specific=0x7ff8e2fc2d07 "") at /home/alice/git/10.2/mysys/safemalloc.c:215
 
#5  0x0000561e605a59d5 in my_free (ptr=0x8f8f8f8f8f8f8f8f) at /home/alice/git/10.2/mysys/my_malloc.c:215
 
#6  0x0000561e5fafd789 in String::free (this=0x7ff8cc013568) at /home/alice/git/10.2/sql/sql_string.h:351
 
#7  0x0000561e6001a38e in Item_json_str_multipath::cleanup (this=0x7ff8cc03e278) at /home/alice/git/10.2/sql/item_jsonfunc.cc:675
 
#8  0x0000561e5fb94fa5 in Item::delete_self (this=0x7ff8cc03e278) at /home/alice/git/10.2/sql/item.h:1813
 
#9  0x0000561e5fb8c01e in Query_arena::free_items (this=0x7ff8cc038810) at /home/alice/git/10.2/sql/sql_class.cc:3516
 
#10 0x0000561e5fcd05f8 in closefrm (table=0x7ff8cc03b440) at /home/alice/git/10.2/sql/table.cc:3415
 
#11 0x0000561e5fdb5b79 in intern_close_table (table=0x7ff8cc03b440) at /home/alice/git/10.2/sql/table_cache.cc:222
 
#12 0x0000561e5fdb8609 in tdc_remove_table (thd=0x7ff8cc000b00, remove_type=TDC_RT_REMOVE_ALL, db=0x7ff8cc012a50 "test", table_name=0x7ff8cc012408 "t1", kill_delayed_threads=false) at /home/alice/git/10.2/sql/table_cache.cc:1132
 
#13 0x0000561e5fc8fb72 in mysql_rm_table_no_locks (thd=0x7ff8cc000b00, tables=0x7ff8cc012440, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /home/alice/git/10.2/sql/sql_table.cc:2455
 
#14 0x0000561e5fc8ee54 in mysql_rm_table (thd=0x7ff8cc000b00, tables=0x7ff8cc012440, if_exists=0 '\000', drop_temporary=0 '\000') at /home/alice/git/10.2/sql/sql_table.cc:2085
 
#15 0x0000561e5fbd2ee4 in mysql_execute_command (thd=0x7ff8cc000b00) at /home/alice/git/10.2/sql/sql_parse.cc:4737
 
#16 0x0000561e5fbdcf1b in mysql_parse (thd=0x7ff8cc000b00, rawbuf=0x7ff8cc012378 "drop table t1", length=13, parser_state=0x7ff8e2fc4200, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:7879
 
#17 0x0000561e5fbcacee in dispatch_command (command=COM_QUERY, thd=0x7ff8cc000b00, packet=0x7ff8cc1680b1 "drop table t1", packet_length=13, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:1817
 
#18 0x0000561e5fbc9628 in do_command (thd=0x7ff8cc000b00) at /home/alice/git/10.2/sql/sql_parse.cc:1362
 
#19 0x0000561e5fd14fcc in do_handle_one_connection (connect=0x561e6296c420) at /home/alice/git/10.2/sql/sql_connect.cc:1354
 
#20 0x0000561e5fd14d4c in handle_one_connection (arg=0x561e6296c420) at /home/alice/git/10.2/sql/sql_connect.cc:1260
 
#21 0x0000561e6006d4b8 in pfs_spawn_thread (arg=0x561e62a0edf0) at /home/alice/git/10.2/storage/perfschema/pfs.cc:1862
 
#22 0x00007ff8ed9606ba in start_thread (arg=0x7ff8e2fc5700) at pthread_create.c:333
 
#23 0x00007ff8ecdf53dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Generated at Thu Feb 08 08:05:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.