Description:
Introduction
It has been observed that MySQL 8.0.32 and higher crash when a stored proc is run that takes input parameters and compares at least one of these input parameters against a field in a nested query. For all the cases observed for this issue, the queries run fine in MySQL 5.7, but once the customer upgraded to 8.0.32+, they started experiencing crashes. We have a reproducible test case, but unfortunately our customer has not given us consent to publicly share this reproducible test case. We will therefore provide an analysis of the issue based on investigations using GDB/rr.
Detailed description
Queries that are known to crash are similar to the below:
CREATE DEFINER=`user1`@`localhost` PROCEDURE `db1`.`sp1`(IN param1 int, IN param2 int, IN param3 int, IN param4 int, IN param5 bigint)
BEGIN
DECLARE EXIT HANDLER FOR SQLEXCEPTION
BEGIN
GET DIAGNOSTICS CONDITION 1 @sqlstate = RETURNED_SQLSTATE,
@errno = MYSQL_ERRNO,
@text = MESSAGE_TEXT;
SET @full_error = CONCAT("ERROR ", @errno, " (", @sqlstate, "): ", @text);
SELECT
@full_error;
END;
SELECT SUM(c1alias) FROM
(SELECT COUNT(*) AS c1alias FROM t1 t1alias
JOIN t2 t2alias
ON t1alias.f2 = t2alias.f2
WHERE t1alias.f3 = param1 <---This causes the crash
AND t1alias.f3 IN (SELECT f3 FROM t3 t3alias WHERE t3alias.f3 = t1alias.f3)) alias1;
END
From our investigation, we observed that a query similar to the above crashes the MySQL system if the same query is run against 2 different databases but in the same thread sequentially. For example:
CALL db1.sp1(74222,1,0,102,1000623);CALL db2.sp1(74222,1,0,102,1000623);
Switching back to the details observed in the crash generated by our customer, we see the following stack trace when the segmentation fault occurs:
(rr) bt
#0 0x0000559f8d69c55e in Item_cache::walk (this=0x7fbac47b2328, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item.cc:9580
#1 0x0000559f8d6a493b in Item_ref::walk (this=0x7fbac47b23f0, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item.h:5847
#2 0x0000559f8d719985 in Item_func::walk (this=0x7fbac47b2500, processor=&virtual table offset 752, walk=enum_walk::PREFIX, argument=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item_func.cc:617
#3 0x0000559f8d719985 in Item_func::walk (this=0x7fbac47b26b8, processor=&virtual table offset 752, walk=enum_walk::PREFIX, argument=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item_func.cc:617
#4 0x0000559f8d6c1fda in Item_cond::walk (this=0x7fbac47b27b0, processor=&virtual table offset 752, walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item_cmpfunc.cc:5744
#5 0x0000559f8d2ae25d in Query_block::check_column_privileges (this=0x7fbac47ab530, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2046
#6 0x0000559f8d2ae9f1 in Query_block::check_privileges_for_subqueries (this=0x7fbac47a77f0, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2145
#7 0x0000559f8d2ae67a in Query_block::check_column_privileges (this=0x7fbac47a77f0, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2079
#8 0x0000559f8d2ae9f1 in Query_block::check_privileges_for_subqueries (this=0x7fbac47a2a00, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2145
#9 0x0000559f8d2ae67a in Query_block::check_column_privileges (this=0x7fbac47a2a00, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2079
#10 0x0000559f8d2abfd5 in Sql_cmd_select::check_privileges (this=0x7fbac47b0f58, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:1163
#11 0x0000559f8d2aa983 in Sql_cmd_dml::execute (this=0x7fbac47b0f58, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:732
#12 0x0000559f8d21f6b9 in mysql_execute_command (thd=0x7fbac4694a70, first_level=false) at /github/MySQL/mysql-server/sql/sql_parse.cc:4721
#13 0x0000559f8d0d93d1 in sp_instr_stmt::exec_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4) at /github/MySQL/mysql-server/sql/sp_instr.cc:985
#14 0x0000559f8d0d7f2f in sp_lex_instr::reset_lex_and_exec_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4, open_tables=false)
at /github/MySQL/mysql-server/sql/sp_instr.cc:461
#15 0x0000559f8d0d8a89 in sp_lex_instr::validate_lex_and_execute_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4, open_tables=false)
at /github/MySQL/mysql-server/sql/sp_instr.cc:745
#16 0x0000559f8d0d90a9 in sp_instr_stmt::execute (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4) at /github/MySQL/mysql-server/sql/sp_instr.cc:911
...
By looking at frame 0 we see that the crash occurs due to the example variable being dereferenced:
(rr) frame 0
#0 0x0000559f8d69c55e in Item_cache::walk (this=0x7fbac47b2328, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U")
at /github/MySQL/mysql-server/sql/item.cc:9580
9580 (example && example→walk(processor, walk, arg)) ||
The context of the example variable is shown below:
9578 bool Item_cache::walk(Item_processor processor, enum_walk walk, uchar arg) {
9579 return ((walk & enum_walk::PREFIX) && (this→processor)(arg)) ||
9580 (example && example→walk(processor, walk, arg)) || <----- example is a non-null pointer that is pointing to invalid data as can be seen below.
9581 ((walk & enum_walk::POSTFIX) && (this→*processor)(arg));
9582 }
When we look at the contents of the Item object that example is pointing to, we find that they are invalid, having been filled with the value 0x8f repeatedly:
(rr) p example
$11 = (Item *) 0x7fbac5269ac0
(rr) p *example
$12 = {<Parse_tree_node_tmpl<Parse_context>> = {_vptr.Parse_tree_node_tmpl = 0x8f8f8f8f8f8f8f8f, contextualized = 143}, next_free = 0x8f8f8f8f8f8f8f8f, str_value = {
m_ptr = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239, m_charset = 0x8f8f8f8f8f8f8f8f, m_alloced_length = 2408550287, m_is_alloced = 143},
collation = {collation = 0x8f8f8f8f8f8f8f8f, derivation = 2408550287, repertoire = 2408550287}, item_name = {<Name_string> = {<Simple_cstring> = {
m_str = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239}, <No data fields>}, m_is_autogenerated = 143},
orig_name = {<Name_string> = {<Simple_cstring> = {m_str = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239}, <No data fields>},
m_is_autogenerated = 143}, max_length = 2408550287, marker = 2408550287, cmp_context = -1886417009, m_ref_count = 2408550287, m_abandoned = 143, is_parser_item = 143, is_expensive_cache = -113 '\217',
m_data_type = 143 '\217', fixed = 143, decimals = 143 '\217', m_nullable = 143, null_value = 143, unsigned_flag = 143, m_is_window_function = 143, hidden = 143, m_in_check_constraint_exec_ctx = 143,
static PROP_SUBQUERY = 1 '\001', static PROP_STORED_PROGRAM = 2 '\002', static PROP_AGGREGATION = 4 '\004', static PROP_WINDOW_FUNCTION = 8 '\b', static PROP_ROLLUP_EXPR = 16 '\020',
static PROP_GROUPING_FUNC = 32 ' ', m_accum_properties = 143 '\217'}
How to repeat:
We set a watchpoint on the example variable and run the program backwards to see when it last changed. From the stack trace below, it appears the last time it was touched it was being deleted, yet somehow it is still being accessed later on in the program and causing a crash:
(rr) watch *0x7fbac5269ac0
Hardware watchpoint 2: *0x7fbac5269ac0
(rr) reverse-continue
Continuing.
Thread 2 hit Hardware watchpoint 2: *0x7fbac5269ac0
Old value = -1886417009
New value = -1840105904
__memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:200
200 ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory.
(rr) bt
#0 __memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:200
#1 0x0000559f8d04f38b in TRASH (ptr=0x7fbac5269ac0, length=200) at /github/MySQL/mysql-server/include/memory_debugging.h:72 <--- Function that writes 0x8f repeatedly into the object.
#2 0x0000559f8d073e8e in Item::operator delete (ptr=0x7fbac5269ac0, size=200) at /github/MySQL/mysql-server/sql/item.h:881 <--- delete operator is being called on the object
#3 0x0000559f8d6a6881 in Item_cache_int::~Item_cache_int (this=0x7fbac5269ac0, __in_chrg=<optimized out>) at /github/MySQL/mysql-server/sql/item.h:6788
#4 0x0000559f8d1238de in Item::delete_self (this=0x7fbac5269ac0) at /github/MySQL/mysql-server/sql/item.h:3089
#5 0x0000559f8d11cdbd in Query_arena::free_items (this=0x7fbac4694a78) at /github/MySQL/mysql-server/sql/sql_class.cc:2016
#6 0x0000559f8d11be5e in THD::cleanup_after_query (this=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_class.cc:1804
#7 0x0000559f8d0c76fc in sp_head::execute (this=0x7fbac4795800, thd=0x7fbac4694a70, merge_da_on_success=true) at /github/MySQL/mysql-server/sql/sp_head.cc:2242
#8 0x0000559f8d0c976a in sp_head::execute_procedure (this=0x7fbac4795800, thd=0x7fbac4694a70, args=0x7fbac469f0e0) at /github/MySQL/mysql-server/sql/sp_head.cc:2866
#9 0x0000559f8d9ad53b in Sql_cmd_call::execute_inner (this=0x7fbac469fc98, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_call.cc:235
#10 0x0000559f8d2aacfd in Sql_cmd_dml::execute (this=0x7fbac469fc98,
...
Description: Introduction It has been observed that MySQL 8.0.32 and higher crash when a stored proc is run that takes input parameters and compares at least one of these input parameters against a field in a nested query. For all the cases observed for this issue, the queries run fine in MySQL 5.7, but once the customer upgraded to 8.0.32+, they started experiencing crashes. We have a reproducible test case, but unfortunately our customer has not given us consent to publicly share this reproducible test case. We will therefore provide an analysis of the issue based on investigations using GDB/rr. Detailed description Queries that are known to crash are similar to the below: CREATE DEFINER=`user1`@`localhost` PROCEDURE `db1`.`sp1`(IN param1 int, IN param2 int, IN param3 int, IN param4 int, IN param5 bigint) BEGIN DECLARE EXIT HANDLER FOR SQLEXCEPTION BEGIN GET DIAGNOSTICS CONDITION 1 @sqlstate = RETURNED_SQLSTATE, @errno = MYSQL_ERRNO, @text = MESSAGE_TEXT; SET @full_error = CONCAT("ERROR ", @errno, " (", @sqlstate, "): ", @text); SELECT @full_error; END; SELECT SUM(c1alias) FROM (SELECT COUNT(*) AS c1alias FROM t1 t1alias JOIN t2 t2alias ON t1alias.f2 = t2alias.f2 WHERE t1alias.f3 = param1 <---This causes the crash AND t1alias.f3 IN (SELECT f3 FROM t3 t3alias WHERE t3alias.f3 = t1alias.f3)) alias1; END From our investigation, we observed that a query similar to the above crashes the MySQL system if the same query is run against 2 different databases but in the same thread sequentially. For example: CALL db1.sp1(74222,1,0,102,1000623);CALL db2.sp1(74222,1,0,102,1000623); Switching back to the details observed in the crash generated by our customer, we see the following stack trace when the segmentation fault occurs: (rr) bt #0 0x0000559f8d69c55e in Item_cache::walk (this=0x7fbac47b2328, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item.cc:9580 #1 0x0000559f8d6a493b in Item_ref::walk (this=0x7fbac47b23f0, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item.h:5847 #2 0x0000559f8d719985 in Item_func::walk (this=0x7fbac47b2500, processor=&virtual table offset 752, walk=enum_walk::PREFIX, argument=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item_func.cc:617 #3 0x0000559f8d719985 in Item_func::walk (this=0x7fbac47b26b8, processor=&virtual table offset 752, walk=enum_walk::PREFIX, argument=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item_func.cc:617 #4 0x0000559f8d6c1fda in Item_cond::walk (this=0x7fbac47b27b0, processor=&virtual table offset 752, walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item_cmpfunc.cc:5744 #5 0x0000559f8d2ae25d in Query_block::check_column_privileges (this=0x7fbac47ab530, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2046 #6 0x0000559f8d2ae9f1 in Query_block::check_privileges_for_subqueries (this=0x7fbac47a77f0, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2145 #7 0x0000559f8d2ae67a in Query_block::check_column_privileges (this=0x7fbac47a77f0, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2079 #8 0x0000559f8d2ae9f1 in Query_block::check_privileges_for_subqueries (this=0x7fbac47a2a00, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2145 #9 0x0000559f8d2ae67a in Query_block::check_column_privileges (this=0x7fbac47a2a00, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:2079 #10 0x0000559f8d2abfd5 in Sql_cmd_select::check_privileges (this=0x7fbac47b0f58, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:1163 #11 0x0000559f8d2aa983 in Sql_cmd_dml::execute (this=0x7fbac47b0f58, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_select.cc:732 #12 0x0000559f8d21f6b9 in mysql_execute_command (thd=0x7fbac4694a70, first_level=false) at /github/MySQL/mysql-server/sql/sql_parse.cc:4721 #13 0x0000559f8d0d93d1 in sp_instr_stmt::exec_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4) at /github/MySQL/mysql-server/sql/sp_instr.cc:985 #14 0x0000559f8d0d7f2f in sp_lex_instr::reset_lex_and_exec_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4, open_tables=false) at /github/MySQL/mysql-server/sql/sp_instr.cc:461 #15 0x0000559f8d0d8a89 in sp_lex_instr::validate_lex_and_execute_core (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4, open_tables=false) at /github/MySQL/mysql-server/sql/sp_instr.cc:745 #16 0x0000559f8d0d90a9 in sp_instr_stmt::execute (this=0x7fbac47b11e0, thd=0x7fbac4694a70, nextp=0x7fba918e5bc4) at /github/MySQL/mysql-server/sql/sp_instr.cc:911 ... By looking at frame 0 we see that the crash occurs due to the example variable being dereferenced: (rr) frame 0 #0 0x0000559f8d69c55e in Item_cache::walk (this=0x7fbac47b2328, processor=&virtual Item::check_column_privileges(unsigned char*), walk=enum_walk::PREFIX, arg=0x7fbac4694a70 "\220pR\222\237U") at /github/MySQL/mysql-server/sql/item.cc:9580 9580 (example && example→walk(processor, walk, arg)) || The context of the example variable is shown below: 9578 bool Item_cache::walk(Item_processor processor, enum_walk walk, uchar arg) { 9579 return ((walk & enum_walk::PREFIX) && (this→processor)(arg)) || 9580 (example && example→walk(processor, walk, arg)) || <----- example is a non-null pointer that is pointing to invalid data as can be seen below. 9581 ((walk & enum_walk::POSTFIX) && (this→*processor)(arg)); 9582 } When we look at the contents of the Item object that example is pointing to, we find that they are invalid, having been filled with the value 0x8f repeatedly: (rr) p example $11 = (Item *) 0x7fbac5269ac0 (rr) p *example $12 = {<Parse_tree_node_tmpl<Parse_context>> = {_vptr.Parse_tree_node_tmpl = 0x8f8f8f8f8f8f8f8f, contextualized = 143}, next_free = 0x8f8f8f8f8f8f8f8f, str_value = { m_ptr = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239, m_charset = 0x8f8f8f8f8f8f8f8f, m_alloced_length = 2408550287, m_is_alloced = 143}, collation = {collation = 0x8f8f8f8f8f8f8f8f, derivation = 2408550287, repertoire = 2408550287}, item_name = {<Name_string> = {<Simple_cstring> = { m_str = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239}, <No data fields>}, m_is_autogenerated = 143}, orig_name = {<Name_string> = {<Simple_cstring> = {m_str = 0x8f8f8f8f8f8f8f8f <error: Cannot access memory at address 0x8f8f8f8f8f8f8f8f>, m_length = 10344644715844964239}, <No data fields>}, m_is_autogenerated = 143}, max_length = 2408550287, marker = 2408550287, cmp_context = -1886417009, m_ref_count = 2408550287, m_abandoned = 143, is_parser_item = 143, is_expensive_cache = -113 '\217', m_data_type = 143 '\217', fixed = 143, decimals = 143 '\217', m_nullable = 143, null_value = 143, unsigned_flag = 143, m_is_window_function = 143, hidden = 143, m_in_check_constraint_exec_ctx = 143, static PROP_SUBQUERY = 1 '\001', static PROP_STORED_PROGRAM = 2 '\002', static PROP_AGGREGATION = 4 '\004', static PROP_WINDOW_FUNCTION = 8 '\b', static PROP_ROLLUP_EXPR = 16 '\020', static PROP_GROUPING_FUNC = 32 ' ', m_accum_properties = 143 '\217'} How to repeat: We set a watchpoint on the example variable and run the program backwards to see when it last changed. From the stack trace below, it appears the last time it was touched it was being deleted, yet somehow it is still being accessed later on in the program and causing a crash: (rr) watch *0x7fbac5269ac0 Hardware watchpoint 2: *0x7fbac5269ac0 (rr) reverse-continue Continuing. Thread 2 hit Hardware watchpoint 2: *0x7fbac5269ac0 Old value = -1886417009 New value = -1840105904 __memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:200 200 ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory. (rr) bt #0 __memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:200 #1 0x0000559f8d04f38b in TRASH (ptr=0x7fbac5269ac0, length=200) at /github/MySQL/mysql-server/include/memory_debugging.h:72 <--- Function that writes 0x8f repeatedly into the object. #2 0x0000559f8d073e8e in Item::operator delete (ptr=0x7fbac5269ac0, size=200) at /github/MySQL/mysql-server/sql/item.h:881 <--- delete operator is being called on the object #3 0x0000559f8d6a6881 in Item_cache_int::~Item_cache_int (this=0x7fbac5269ac0, __in_chrg=<optimized out>) at /github/MySQL/mysql-server/sql/item.h:6788 #4 0x0000559f8d1238de in Item::delete_self (this=0x7fbac5269ac0) at /github/MySQL/mysql-server/sql/item.h:3089 #5 0x0000559f8d11cdbd in Query_arena::free_items (this=0x7fbac4694a78) at /github/MySQL/mysql-server/sql/sql_class.cc:2016 #6 0x0000559f8d11be5e in THD::cleanup_after_query (this=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_class.cc:1804 #7 0x0000559f8d0c76fc in sp_head::execute (this=0x7fbac4795800, thd=0x7fbac4694a70, merge_da_on_success=true) at /github/MySQL/mysql-server/sql/sp_head.cc:2242 #8 0x0000559f8d0c976a in sp_head::execute_procedure (this=0x7fbac4795800, thd=0x7fbac4694a70, args=0x7fbac469f0e0) at /github/MySQL/mysql-server/sql/sp_head.cc:2866 #9 0x0000559f8d9ad53b in Sql_cmd_call::execute_inner (this=0x7fbac469fc98, thd=0x7fbac4694a70) at /github/MySQL/mysql-server/sql/sql_call.cc:235 #10 0x0000559f8d2aacfd in Sql_cmd_dml::execute (this=0x7fbac469fc98, ...