[MDEV-19811] Crash with prepared statement Created: 2019-06-20  Updated: 2023-04-14

Status: Open
Project: MariaDB Server
Component/s: Prepared Statements
Affects Version/s: 10.5.12
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: markus makela Assignee: Dmitry Shulga
Resolution: Unresolved Votes: 0
Labels: None
Environment:

CentOS 7

Issue Links:
Duplicate
is duplicated by MDEV-26357 Crash in Item_param::convert_str_value Closed
is duplicated by MDEV-29539 [ERROR] mysqld got exception 0xc0000005 Open
Relates
relates to MXS-2521 COM_STMT_EXECUTE maybe return empty r... Closed
relates to MXS-3720 idle_session_pool_time should support... Closed

 Description   

Stacktrace:

/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x560ecc80f64e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x560ecc2b0dff]
 
2019-06-20 12:47:14 16 [Warning] Aborted connection 16 to db: 'unconnected' user: 'maxskysql' host: 'maxscale' (Got an error reading communication packets)
 
2019-06-20 12:47:18 18 [Warning] Aborted connection 18 to db: 'unconnected' user: 'maxskysql' host: 'maxscale' (Got an error reading communication packets)
 
sigaction.c:0(__restore_rt)[0x7f8b7a6285e0]
 
/usr/sbin/mysqld(my_string_metadata_get+0x1a)[0x560ecc84a97a]
 
/usr/sbin/mysqld(_ZN10Item_param17convert_str_valueEP3THD+0xd0)[0x560ecc2d2490]
 
/usr/sbin/mysqld(+0x5c107f)[0x560ecc0eb07f]
 
/usr/sbin/mysqld(_ZN18Prepared_statement14set_parametersEP6StringPhS2_+0x6a)[0x560ecc0ef2ea]
 
/usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x37)[0x560ecc0f0417]
 
/usr/sbin/mysqld(+0x5c710f)[0x560ecc0f110f]
 
/usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDPcj+0x27)[0x560ecc0f11a7]
 
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xf60)[0x560ecc0df7b0]
 
/usr/sbin/mysqld(_Z10do_commandP3THD+0x13e)[0x560ecc0e13ee]
 
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1aa)[0x560ecc1b44ba]
 
/usr/sbin/mysqld(handle_one_connection+0x3d)[0x560ecc1b45dd]
 
pthread_create.c:0(start_thread)[0x7f8b7a620e25]
 
/lib64/libc.so.6(clone+0x6d)[0x7f8b78bf834d]

Full crash output:

Jun 20 12:47:10 node-001 mysqld[15624]: 190620 12:47:10 [ERROR] mysqld got signal 11 ;
 
Jun 20 12:47:10 node-001 mysqld[15624]: This could be because you hit a bug. It is also possible that this binary
 
Jun 20 12:47:10 node-001 mysqld[15624]: or one of the libraries it was linked against is corrupt, improperly built,
 
Jun 20 12:47:10 node-001 mysqld[15624]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Jun 20 12:47:10 node-001 mysqld[15624]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Jun 20 12:47:10 node-001 mysqld[15624]: We will try our best to scrape up some info that will hopefully help
 
Jun 20 12:47:10 node-001 mysqld[15624]: diagnose the problem, but since we have already crashed,
 
Jun 20 12:47:10 node-001 mysqld[15624]: something is definitely wrong and this may fail.
 
Jun 20 12:47:10 node-001 mysqld[15624]: Server version: 10.3.16-MariaDB-log
 
Jun 20 12:47:10 node-001 mysqld[15624]: key_buffer_size=134217728
 
Jun 20 12:47:10 node-001 mysqld[15624]: read_buffer_size=131072
 
Jun 20 12:47:10 node-001 mysqld[15624]: max_used_connections=2
 
Jun 20 12:47:10 node-001 mysqld[15624]: max_threads=153
 
Jun 20 12:47:10 node-001 mysqld[15624]: thread_count=11
 
Jun 20 12:47:10 node-001 mysqld[15624]: It is possible that mysqld could use up to
 
Jun 20 12:47:10 node-001 mysqld[15624]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 689022 K  bytes of memory
 
Jun 20 12:47:10 node-001 mysqld[15624]: Hope that's ok; if not, decrease some variables in the equation.
 
Jun 20 12:47:10 node-001 mysqld[15624]: Thread pointer: 0x7f8b34000a88
 
Jun 20 12:47:10 node-001 mysqld[15624]: Attempting backtrace. You can use the following information to find out
 
Jun 20 12:47:10 node-001 mysqld[15624]: where mysqld died. If you see no messages after this, something went
 
Jun 20 12:47:10 node-001 mysqld[15624]: terribly wrong...
 
Jun 20 12:47:10 node-001 mysqld[15624]: stack_bottom = 0x7f8b60843d70 thread_stack 0x49000
 
Jun 20 12:47:10 node-001 mysqld[15624]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x560ecc80f64e]
 
Jun 20 12:47:10 node-001 mysqld[15624]: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x560ecc2b0dff]
 
Jun 20 12:47:14 node-001 mysqld[15624]: 2019-06-20 12:47:14 16 [Warning] Aborted connection 16 to db: 'unconnected' user: 'maxskysql' host: 'maxscale' (Got an error reading communication packets)
 
Jun 20 12:47:18 node-001 mysqld[15624]: 2019-06-20 12:47:18 18 [Warning] Aborted connection 18 to db: 'unconnected' user: 'maxskysql' host: 'maxscale' (Got an error reading communication packets)
 
Jun 20 12:47:18 node-001 mysqld[15624]: sigaction.c:0(__restore_rt)[0x7f8b7a6285e0]
 
Jun 20 12:47:18 node-001 mysqld[15624]: /usr/sbin/mysqld(my_string_metadata_get+0x1a)[0x560ecc84a97a]
 
Jun 20 12:47:18 node-001 mysqld[15624]: /usr/sbin/mysqld(_ZN10Item_param17convert_str_valueEP3THD+0xd0)[0x560ecc2d2490]
 
Jun 20 12:47:18 node-001 mysqld[15624]: /usr/sbin/mysqld(+0x5c107f)[0x560ecc0eb07f]
 
Jun 20 12:47:18 node-001 mysqld[15624]: /usr/sbin/mysqld(_ZN18Prepared_statement14set_parametersEP6StringPhS2_+0x6a)[0x560ecc0ef2ea]
 
Jun 20 12:47:18 node-001 mysqld[15624]: /usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x37)[0x560ecc0f0417]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(+0x5c710f)[0x560ecc0f110f]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDPcj+0x27)[0x560ecc0f11a7]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xf60)[0x560ecc0df7b0]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(_Z10do_commandP3THD+0x13e)[0x560ecc0e13ee]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x1aa)[0x560ecc1b44ba]
 
Jun 20 12:47:19 node-001 mysqld[15624]: /usr/sbin/mysqld(handle_one_connection+0x3d)[0x560ecc1b45dd]
 
Jun 20 12:47:24 node-001 mysqld[15624]: pthread_create.c:0(start_thread)[0x7f8b7a620e25]
 
Jun 20 12:47:24 node-001 mysqld[15624]: /lib64/libc.so.6(clone+0x6d)[0x7f8b78bf834d]
 
Jun 20 12:47:24 node-001 mysqld[15624]: Trying to get some variables.
 
Jun 20 12:47:24 node-001 mysqld[15624]: Some pointers may be invalid and cause the dump to abort.
 
Jun 20 12:47:24 node-001 mysqld[15624]: Query (0x0):
 
Jun 20 12:47:24 node-001 mysqld[15624]: Connection ID (thread ID): 17
 
Jun 20 12:47:24 node-001 mysqld[15624]: Status: NOT_KILLED
 
Jun 20 12:47:24 node-001 mysqld[15624]: 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=
 
Jun 20 12:47:24 node-001 mysqld[15624]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
Jun 20 12:47:24 node-001 mysqld[15624]: information that should help you find out what is causing the crash.
 
Jun 20 12:47:24 node-001 mysqld[15624]: Writing a core file...
 
Jun 20 12:47:24 node-001 mysqld[15624]: Working directory at /var/lib/mysql
 
Jun 20 12:47:24 node-001 mysqld[15624]: Resource Limits:
 
Jun 20 12:47:24 node-001 mysqld[15624]: Limit                     Soft Limit           Hard Limit           Units
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max cpu time              unlimited            unlimited            seconds
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max file size             unlimited            unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max data size             unlimited            unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max stack size            8388608              unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max core file size        0                    unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max resident set          unlimited            unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max processes             3901                 3901                 processes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max open files            16364                16364                files
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max locked memory         65536                65536                bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max address space         unlimited            unlimited            bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max file locks            unlimited            unlimited            locks
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max pending signals       3901                 3901                 signals
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max msgqueue size         819200               819200               bytes
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max nice priority         0                    0
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max realtime priority     0                    0
 
Jun 20 12:47:24 node-001 mysqld[15624]: Max realtime timeout      unlimited            unlimited            us
 
Jun 20 12:47:24 node-001 mysqld[15624]: Core pattern: core

Test case used to reproduce it (it's a MaxScale system test so it doesn't compile straight out of the box):

    TestConnections test(argc, argv);
 
    test.maxscales->connect();
 
 
 
    auto conn = test.maxscales->conn_rwsplit[0];
 
 
 
    test.try_query(conn, "DROP TABLE double_execute;");
 
    test.try_query(conn, "CREATE TABLE double_execute(a int);");
 
    test.try_query(conn, "INSERT INTO double_execute VALUES (123), (456)");
 
 
 
    auto stmt = mysql_stmt_init(conn);
 
    std::string sql = "select a, @@server_id from double_execute where a = ?";
 
    test.expect(mysql_stmt_prepare(stmt, sql.c_str(), sql.length()) == 0,
 
                "Prepare should work: %s", mysql_error(conn));
 
 
 
    int data[2] = {0, 0};
 
    MYSQL_BIND my_bind[2] = {};
 
    char is_null = 0;
 
    my_bind[0].buffer_type = MYSQL_TYPE_LONG;
 
    my_bind[0].buffer = &data[0];
 
    my_bind[0].buffer_length = sizeof(data[0]);
 
    my_bind[0].is_null = &is_null;
 
    my_bind[1].buffer_type = MYSQL_TYPE_LONG;
 
    my_bind[1].buffer = &data[1];
 
    my_bind[1].buffer_length = sizeof(data[2]);
 
    my_bind[1].is_null = &is_null;
 
    data[1] = 123;
 
    test.expect(mysql_stmt_bind_param(stmt, my_bind) == 0, "Bind: %s", mysql_stmt_error(stmt));
 
 
 
    // The first execute is done on the master                                                                                                                                                                                                                
    test.try_query(conn, "BEGIN");
 
 
 
    test.expect(mysql_stmt_execute(stmt) == 0, "First execute should work: %s", mysql_stmt_error(stmt));
 
    data[0] = 0;
 
 
 
    mysql_stmt_store_result(stmt);
 
    test.expect(mysql_stmt_fetch(stmt) == 0, "First fetch of first execute should work");
 
    test.expect(data[0] == 123, "Query should return one row with value 123: `%d`", data[0]);
 
    test.expect(mysql_stmt_fetch(stmt) != 0, "Second fetch of first execute should NOT work");
 
 
 
    test.try_query(conn, "COMMIT");
 
 
 
 
 
    // The second execute goes to a slave, no new parameters are sent in it                                                                                                                                                                                   
    data[0] = 123;
 
    test.expect(mysql_stmt_execute(stmt) == 0, "Second execute should work: %s", mysql_stmt_error(stmt));
 
    data[0] = 0;
 
 
 
    mysql_stmt_store_result(stmt);
 
 
 
    test.expect(mysql_stmt_fetch(stmt) == 0, "First fetch of second execute should work");
 
    test.expect(data[0] == 123, "Query should return one row with value 123: `%d`", data[0]);
 
    test.expect(mysql_stmt_fetch(stmt) != 0, "Second fetch of second execute should NOT work");
 
 
 
    mysql_stmt_close(stmt);



 Comments   
Comment by markus makela [ 2019-06-20 ]

A slightly cleaner test case:

void test1(MYSQL* conn)
 
{
 
    mysql_query(conn, "DROP TABLE double_execute;");
 
    mysql_query(conn, "CREATE TABLE double_execute(a int);");
 
    mysql_query(conn, "INSERT INTO double_execute VALUES (123), (456)");
 
 
 
    auto stmt = mysql_stmt_init(conn);
 
    std::string sql = "select a, @@server_id from double_execute where a = ?";
 
    mysql_stmt_prepare(stmt, sql.c_str(), sql.length());
 
 
 
    int data[2] = {0, 0};
 
    MYSQL_BIND my_bind[2] = {};
 
    char is_null = 0;
 
    my_bind[0].buffer_type = MYSQL_TYPE_LONG;
 
    my_bind[0].buffer = &data[0];
 
    my_bind[0].buffer_length = sizeof(data[0]);
 
    my_bind[0].is_null = &is_null;
 
    my_bind[1].buffer_type = MYSQL_TYPE_LONG;
 
    my_bind[1].buffer = &data[1];
 
    my_bind[1].buffer_length = sizeof(data[2]);
 
    my_bind[1].is_null = &is_null;
 
    data[1] = 123;
 
    mysql_stmt_bind_param(stmt, my_bind);
 
 
 
    // The first execute is done on the master                                                                                                                                                                                                                
    mysql_query(conn, "BEGIN");
 
 
 
    mysql_stmt_execute(stmt);
 
    data[0] = 0;
 
 
 
    mysql_stmt_store_result(stmt);
 
    mysql_stmt_fetch(stmt);
 
    mysql_stmt_fetch(stmt);
 
 
 
    mysql_query(conn, "COMMIT");
 
 
 
 
 
    // The second execute goes to a slave, no new parameters are sent in it                                                                                                                                                                                   
    data[0] = 123;
 
    mysql_stmt_execute(stmt);
 
    data[0] = 0;
 
 
 
    mysql_stmt_store_result(stmt);
 
 
 
    mysql_stmt_fetch(stmt);
 
    mysql_stmt_fetch(stmt);
 
    mysql_stmt_close(stmt);
 
}

Comment by markus makela [ 2019-06-25 ]

Wrote a test case that reproduces it when run through MaxScale but not when done directly on the server: https://gist.github.com/markus456/7115cc03f66aad9f756b6e3de7cbf7f9

Comment by markus makela [ 2019-06-25 ]

My theory for the crash is that the second execution of the COM_STMT_EXECUTE doesn't have the required metadata and the server relies on them being present at least once.

Update: Managed to reproduce it by modifying the connector to never send the field types to the server.

Comment by markus makela [ 2021-08-13 ]

Still happens with 10.5.12.

Comment by Dmitry Shulga [ 2023-04-14 ]

10.3 is EOL so removed this version from a list of affected server versions.

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