[MDEV-25684] Crash in THD::find_temporary_table while calling spider_direct_sql UDF without temporary table created Created: 2021-05-16  Updated: 2021-11-23  Resolved: 2021-09-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Spider
Affects Version/s: 10.5.9, 10.5.10, 10.6
Fix Version/s: 10.5.13, 10.6.5

Type: Bug Priority: Major
Reporter: Valerii Kravchuk Assignee: Nayuta Yanagisawa (Inactive)
Resolution: Fixed Votes: 0
Labels: not-10.2, not-10.3, not-10.4

Issue Links:
Blocks

 Description   

With the following ODBC data source defined and working (latest MariaDB Connector/ODBC):

[root@f4c27077179a /]# cat /etc/odbcinst.ini
...
# MariaDB 10.3.11 driver installed manually
[MariaDB]
Description     = MariaDB Connector/ODBC v. 3.1.11
Driver64                = /mariadb-connector-odbc-3.1.11-centos7-amd64/lib64/mariadb/libmaodbc.so
 
[root@f4c27077179a /]# cat /etc/odbc.ini
[maria]
Description     = Local MariaDB server
Driver          = MariaDB
SERVER          = 127.0.0.1
PORT            = 3306
USER            = u1
PASSWORD        = very_complex_Pasword_1
DATABASE        = test
[root@f4c27077179a /]#

[root@f4c27077179a /]# isql MariaDB_local_DSN
+---------------------------------------+
| Connected!                            |
|                                       |
| sql-statement                         |
| help [tablename]                      |
| quit                                  |
|                                       |
+---------------------------------------+
SQL> select * from t1;
+------------+------------+
| id         | c1         |
+------------+------------+
| 1          | 1          |
| 2          | 2          |
+------------+------------+
SQLRowCount returns 2
2 rows fetched
SQL> quit

Let's try to use Spider UDF in a lame way, forgetting to create temporary table tmp of the proper structure:

[root@f4c27077179a /]# mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 23
Server version: 10.5.9-6-MariaDB-enterprise MariaDB Enterprise Server
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MariaDB [(none)]> select * from test.t1;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.001 sec)
 
MariaDB [(none)]> select spider_direct_sql('select * from t1', 'tmp', 'wrapper "odbc", DSN "maria"');
ERROR 2013 (HY000): Lost connection to MySQL server during query

Server crashed:

 
[root@f4c27077179a /]# tail -100 /var/lib/mysql/f4c27077179a.err
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fccd8053c90 thread_stack 0x49000
??:0(my_print_stacktrace)[0x55ec63f2ec0e]
??:0(handle_fatal_signal)[0x55ec63906207]
sigaction.c:0(__restore_rt)[0x7fccdd7ca630]
??:0(THD::find_temporary_table(char const*, unsigned int, THD::Temporary_table_state))[0x55ec638843ff]
??:0(THD::find_and_use_tmp_table(TABLE_LIST const*, TABLE**))[0x55ec638845a1]
??:0(THD::open_temporary_table(TABLE_LIST*))[0x55ec63884731]
??:0(spider_find_temporary_table(THD*, TABLE_LIST*))[0x7fccd81d6211]
??:0(spider_direct_sql_body(st_udf_init*, st_udf_args*, char*, char*, char))[0x7fccd82225ff]
??:0(Item_func_udf_int::val_int())[0x55ec6397d20e]
??:0(Type_handler::Item_send_longlong(Item*, Protocol*, st_value*) const)[0x55ec63861209]
??:0(Protocol::send_result_set_row(List<Item>*))[0x55ec6363e930]
??:0(select_send::send_data(List<Item>&))[0x55ec636afc52]
??:0(JOIN::exec_inner())[0x55ec6375fe9a]
??:0(JOIN::exec())[0x55ec637602d3]
??:0(mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x55ec6375e4ae]
??:0(handle_select(THD*, LEX*, select_result*, unsigned long))[0x55ec6375eff4]
/usr/sbin/mariadbd(+0x634643)[0x55ec635c0643]
??:0(mysql_execute_command(THD*))[0x55ec63702784]
??:0(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55ec637059ba]
??:0(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55ec63707af3]
??:0(do_command(THD*))[0x55ec6370966b]
??:0(do_handle_one_connection(CONNECT*, bool))[0x55ec637f5199]
??:0(handle_one_connection)[0x55ec637f5434]
??:0(MyCTX_nopad::finish(unsigned char*, unsigned int*))[0x55ec63b7bc1d]
pthread_create.c:0(start_thread)[0x7fccdd7c2ea5]
??:0(__clone)[0x7fccdb95a96d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fcc98030e30): select spider_direct_sql('select * from t1', 'tmp', 'wrapper "odbc", DSN "maria"')
 
Connection ID (thread ID): 23
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=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,not_null_range_scan=off
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
information that should help you find out what is causing the crash.
Writing a core file...
Working directory at /var/lib/mysql
Resource Limits:
Limit                     Soft Limit           Hard Limit           Units
Max cpu time              unlimited            unlimited            seconds
Max file size             unlimited            unlimited            bytes
Max data size             unlimited            unlimited            bytes
Max stack size            8388608              unlimited            bytes
Max core file size        unlimited            unlimited            bytes
Max resident set          unlimited            unlimited            bytes
Max processes             unlimited            unlimited            processes
Max open files            1048576              1048576              files
Max locked memory         65536                65536                bytes
Max address space         unlimited            unlimited            bytes
Max file locks            unlimited            unlimited            locks
Max pending signals       14634                14634                signals
Max msgqueue size         819200               819200               bytes
Max nice priority         0                    0
Max realtime priority     0                    0
Max realtime timeout      unlimited            unlimited            us
Core pattern: |/usr/share/apport/apport %p %s %c %d %P %E
 
210516 10:10:55 mysqld_safe Number of processes running now: 0
210516 10:10:55 mysqld_safe mysqld restarted
2021-05-16 10:10:55 0 [Note] /usr/sbin/mariadbd (mysqld 10.5.9-6-MariaDB-enterprise) starting as process 863 ...
2021-05-16 10:10:55 0 [Note] mariadbd: Aria engine: starting recovery
recovered pages: 0% 37% 75% 87% 100% (0.0 seconds); tables to flush: 1 0
 (0.0 seconds);
2021-05-16 10:10:55 0 [Note] mariadbd: Aria engine: recovery done
2021-05-16 10:10:55 0 [Note] InnoDB: Uses event mutexes
2021-05-16 10:10:55 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2021-05-16 10:10:55 0 [Note] InnoDB: Number of pools: 1
2021-05-16 10:10:55 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2021-05-16 10:10:55 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2021-05-16 10:10:55 0 [Note] InnoDB: Using Linux native AIO
2021-05-16 10:10:55 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2021-05-16 10:10:55 0 [Note] InnoDB: Completed initialization of buffer pool
2021-05-16 10:10:55 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-05-16 10:10:55 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=45106,45106
2021-05-16 10:10:55 0 [Note] InnoDB: Starting final batch to recover 12 pages from redo log.
2021-05-16 10:10:56 0 [Note] InnoDB: 128 rollback segments are active.
2021-05-16 10:10:56 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-05-16 10:10:56 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-05-16 10:10:56 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-05-16 10:10:56 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-05-16 10:10:56 0 [Note] InnoDB: 10.5.9 started; log sequence number 48667; transaction id 35
2021-05-16 10:10:56 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-05-16 10:10:56 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-05-16 10:10:56 server_audit: MariaDB Audit Plugin version 2.0.4 STARTED.
2021-05-16 10:10:56 server_audit: Query cache is enabled with the TABLE events. Some table reads can be veiled.
2021-05-16 10:10:56 0 [Note] InnoDB: Buffer pool(s) load completed at 210516 10:10:56
2021-05-16 10:10:56 0 [Note] Recovering after a crash using tc.log
2021-05-16 10:10:56 0 [Note] Starting crash recovery...
2021-05-16 10:10:56 0 [Note] Crash recovery finished.
2021-05-16 10:10:56 0 [Note] Server socket created on IP: '::'.
2021-05-16 10:10:56 0 [Note] Reading of all Master_info entries succeeded
2021-05-16 10:10:56 0 [Note] Added new Master_info '' to hash table
2021-05-16 10:10:56 0 [Note] /usr/sbin/mariadbd: ready for connections.
Version: '10.5.9-6-MariaDB-enterprise'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Enterprise Server
[root@f4c27077179a /]#

This should not happen. We should at least check that the table with that name exists and produce error if it does not.



 Comments   
Comment by Valerii Kravchuk [ 2021-05-16 ]

Actually this happens with Community and 10.5.10 as well, and not only in ODBC context:

...
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Server version: 10.5.10-MariaDB
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: key_buffer_size=134217728
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: read_buffer_size=131072
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: max_used_connections=1
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: max_threads=153
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: thread_count=21
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: It is possible that mysqld could use up to
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467871 K bytes of memory
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Hope that's ok; if not, decrease some variables in the equation.
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Thread pointer: 0x7f603c0009b8
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Attempting backtrace. You can use the following information to find out
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: where mysqld died. If you see no messages after this, something went
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: terribly wrong...
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: stack_bottom = 0x7f61080bfc90 thread_stack 0x49000
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(my_print_stacktrace)[0x55717b2e9dfe]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(handle_fatal_signal)[0x55717acea3b7]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: sigaction.c:0(__restore_rt)[0x7f612398d630]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(THD::find_temporary_table(char const*, unsigned int, THD::Temporary_table_state))[0x55717ac68aff]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(THD::find_and_use_tmp_table(TABLE_LIST const*, TABLE**))[0x55717ac68ca1]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(THD::open_temporary_table(TABLE_LIST*))[0x55717ac68e31]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(spider_find_temporary_table(THD*, TABLE_LIST*))[0x7f60d431b441]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(spider_direct_sql_body(st_udf_init*, st_udf_args*, char*, char*, char))[0x7f60d436843f]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(Item_func_udf_int::val_int())[0x55717ad60e9e]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(Type_handler::Item_send_longlong(Item*, Protocol*, st_value*) const)[0x55717ac42f19]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(Protocol::send_result_set_row(List<Item>*))[0x55717aa21090]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(select_send::send_data(List<Item>&))[0x55717aa92ca2]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(JOIN::exec_inner())[0x55717ab4377a]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(JOIN::exec())[0x55717ab43c93]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(handle_select(THD*, LEX*, select_result*, unsigned long))[0x55717ab428d4]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: /usr/sbin/mariadbd(+0x63962c)[0x55717a9a462c]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(mysql_execute_command(THD*))[0x55717aae5e13]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55717aae84fa]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55717aaeb223]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(do_command(THD*))[0x55717aaec95f]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(do_handle_one_connection(CONNECT*, bool))[0x55717abd7c02]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(handle_one_connection)[0x55717abd7ec4]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(MyCTX_nopad::finish(unsigned char*, unsigned int*))[0x55717af3bf3d]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: pthread_create.c:0(start_thread)[0x7f6123985ea5]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ??:0(__clone)[0x7f6122ea18dd]
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Trying to get some variables.
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Some pointers may be invalid and cause the dump to abort.
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Query (0x7f603c010360): SELECT SPIDER_DIRECT_SQL('select col_a from tmp_a', 'tmp_c'
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: ,'srv "maria_1"') AS "xx"
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Connection ID (thread ID): 24
May 16 21:19:45 LINXTD-MARIAP02 mariadbd[49029]: Status: NOT_KILLED 
...

So, it's a common Spider crash problem.

Comment by Nayuta Yanagisawa (Inactive) [ 2021-08-11 ]

I confirmed that the bug is reproducible on 10.5.9.

MariaDB [(none)]> create server node1 foreign data wrapper mysql options (host '127.0.0.1', database 'test', user 'root', port 16000);
Query OK, 0 rows affected (0.003 sec)
 
MariaDB [(none)]> SET @@session.spider_same_server_link = ON;
Query OK, 0 rows affected (0.001 sec)
 
MariaDB [(none)]> SELECT SPIDER_DIRECT_SQL('SELECT * FROM s', 'tmp', 'srv "node1"');
ERROR 2013 (HY000): Lost connection to MySQL server during query

Comment by Nayuta Yanagisawa (Inactive) [ 2021-08-11 ]

The bug does not reproduce on 10.2, 10.3, 10.4.

MariaDB [(none)]> SELECT SPIDER_DIRECT_SQL('SELECT * FROM s', 'tmp', 'srv "node1"');
ERROR 12703 (HY000): Temporary table '.tmp' is not found

Comment by Nayuta Yanagisawa (Inactive) [ 2021-08-11 ]

The result of git-bisecting:

91ffdc8380ab48a2d57dc81472beb80af115318f is the first bad commit
commit 91ffdc8380ab48a2d57dc81472beb80af115318f
Author: Monty <monty@mariadb.org>
Date:   Mon Apr 6 15:41:33 2020 +0300
 
    Don't try to open temporary tables if there are no temporary tables.
 
    This was done to increase performance when not using temporary tables
    as checking if a table is a temporary table involves a lot of code.
 
 sql/sql_base.cc         | 15 ++++++++-------
 sql/sql_class.h         |  2 +-
 sql/sql_cte.cc          |  4 +++-
 sql/temporary_tables.cc | 13 +++++++++----
 4 files changed, 21 insertions(+), 13 deletions(-)
bisect run success

https://github.com/MariaDB/server/commit/91ffdc8380ab48a2d57dc81472beb80af115318f

Comment by Nayuta Yanagisawa (Inactive) [ 2021-08-11 ]

serg Please review https://github.com/MariaDB/server/commit/2e6d5d6d317b015c0c9a6e33df9185141d0acade

Comment by Nayuta Yanagisawa (Inactive) [ 2021-08-11 ]

serg I updated the fix. Please see this one instead. https://github.com/MariaDB/server/commit/6b60e332d569d217b3c57dff43822c89dc563002

Comment by Sergei Golubchik [ 2021-09-03 ]

6b60e332d569d is ok to push.
thanks!

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