Bug #93812 Inserting a date that exceeds column length when log_bin closed will core dump
Submitted: 4 Jan 6:38 Modified: 11 Mar 13:50
Reporter: jinming liao Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: DML Severity:S6 (Debug Builds)
Version:8.0.13 OS:CentOS (CentOS Linux release 7.2.1511)
Assigned to: CPU Architecture:x86 (Intel(R) Xeon(R) Gold 6161 CPU @ 2.20GHz)

[4 Jan 6:38] jinming liao
Description:
1. Close the bin log by using skip-log-bin in my.cnf.

2. CREATE TABLE - column with date and time function as DEFAULT.
   For example:
    CREATE DATABASE a;
    USE a;
    CREATE TABLE t1 (a datetime, b varchar(10) DEFAULT (localtimestamp()));
    INSERT INTO t1(a) VALUES (now());

3. Return ERROR: ERROR 2013 (HY000): Lost connection to MySQL server during query

4. The process mysqld is killed, and a core file is generated.
   The stack is as follows:

#0  0x00007f8a96ebe9b1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000416cc46 in my_write_core (sig=6) at /xcode/src/mysql-8.0.13/mysys/stacktrace.cc:278
#2  0x0000000002f39803 in handle_fatal_signal (sig=6) at /xcode/src/mysql-8.0.13/sql/signal_handler.cc:249
#3  <signal handler called>
#4  0x00007f8a953e31f7 in raise () from /lib64/libc.so.6
#5  0x00007f8a953e48e8 in abort () from /lib64/libc.so.6
#6  0x00007f8a953dc266 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f8a953dc312 in __assert_fail () from /lib64/libc.so.6
#8  0x0000000003303db0 in Sql_cmd_insert_values::execute_inner (this=0x7f89d01178e0, thd=0x7f89d0000be0) at /xcode/src/mysql-8.0.13/sql/sql_insert.cc:717
#9  0x0000000002df838e in Sql_cmd_dml::execute (this=0x7f89d01178e0, thd=0x7f89d0000be0) at /xcode/src/mysql-8.0.13/sql/sql_select.cc:595
#10 0x0000000002d99452 in mysql_execute_command (thd=0x7f89d0000be0, first_level=true) at /xcode/src/mysql-8.0.13/sql/sql_parse.cc:3325
#11 0x0000000002d9e88e in mysql_parse (thd=0x7f89d0000be0, parser_state=0x7f8a7c536220, force_primary_storage_engine=false) at /xcode/src/mysql-8.0.13/sql/sql_parse.cc:5041
#12 0x0000000002d94cd3 in dispatch_command (thd=0x7f89d0000be0, com_data=0x7f8a7c536b80, command=COM_QUERY) at /xcode/src/mysql-8.0.13/sql/sql_parse.cc:1687
#13 0x0000000002d933f9 in do_command (thd=0x7f89d0000be0) at /xcode/src/mysql-8.0.13/sql/sql_parse.cc:1260
#14 0x0000000002f2627c in handle_connection (arg=0x734a490) at /xcode/src/mysql-8.0.13/sql/conn_handler/connection_handler_per_thread.cc:308
#15 0x0000000004253fba in pfs_spawn_thread (arg=0x742cb40) at /xcode/src/mysql-8.0.13/storage/perfschema/pfs.cc:2836
#16 0x00007f8a96eb9e25 in start_thread () from /lib64/libpthread.so.0
#17 0x00007f8a954a634d in clone () from /lib64/libc.so.6

5. Reason:
(1)sql_insert.cc:611  if (write_record(thd, insert_table, &info, &update))

   This line will set the value of thd->m_stmt_da->m_status is DA_ERROR, because the length of default value is greater then 10.

(2)sql_insert.cc:666  thd->clear_error();

if (!has_error || thd->get_transaction()->cannot_safely_rollback(Transaction_ctx::STMT)) {
  if (mysql_bin_log.is_open()) {
    int errcode = 0;
    if (!has_error) {
      thd->clear_error();
    }
  }
}

If the log_bin is open, thd->m_stmt_da->m_status is clear, and be set DA_EMPTY, and  the return value of thd->get_stmt_da()->is_error() is false.

(3)sql_insert.cc:717  DBUG_ASSERT(has_error == thd->get_stmt_da()->is_error());

If the log_bin is closed, the return value of thd->get_stmt_da()->is_error() is true, but has_error is false, so core dump.

How to repeat:
1. Disable the log-bin, and enable the core-file in my.cnf.
   [mysqld]
   ...
   skip-log-bin
   core-file
2. Initialize and start MySQL, run the following commands :
   CREATE DATABASE a;
   USE a;
   CREATE TABLE t1 (a datetime, b varchar(10) DEFAULT (localtimestamp()));
   INSERT INTO t1(a) VALUES (now());
3. Use gdb to open the core file for analysis.
[4 Jan 6:45] Umesh Shastry
Hello jinming,

Thank you for the report and test case.
Observed that 8.0.13 debug build is affected.

regards,
Umesh
[4 Jan 6:47] Umesh Shastry
- 8.0.13 debug build

rm -rf 93775
bin/mysqld-debug --initialize-insecure --basedir=$PWD --datadir=$PWD/93775 --log-error-verbosity=3 --skip-log-bin
bin/mysqld-debug --no-defaults --basedir=$PWD --datadir=$PWD/93775 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/93775/log.err --log-error-verbosity=3 --skip-log-bin 2>&1 &

bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 8.0.13-debug MySQL Community Server - GPL - Debug

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>     CREATE DATABASE a;
Query OK, 1 row affected (0.03 sec)

mysql>     USE a;
Database changed
mysql>     CREATE TABLE t1 (a datetime, b varchar(10) DEFAULT (localtimestamp()));
Query OK, 0 rows affected (0.03 sec)

mysql>     INSERT INTO t1(a) VALUES (now());
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> \q
Bye
[3]-  Aborted                 (core dumped) bin/mysqld-debug --no-defaults --basedir=$PWD --datadir=$PWD/93775 --core-file --socket=/tmp/mysql_ushastry.sock --port=3333 --log-error=$PWD/93775/log.err --log-error-verbosity=3 --skip-log-bin 2>&1

(gdb) bt
#0  0x00007f3d32be3771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000003e25a74 in my_write_core (sig=6) at ../../mysql-8.0.13/mysys/stacktrace.cc:278
#2  0x0000000002c1ba5d in handle_fatal_signal (sig=6) at ../../mysql-8.0.13/sql/signal_handler.cc:249
#3  <signal handler called>
#4  0x00007f3d30f365d7 in raise () from /lib64/libc.so.6
#5  0x00007f3d30f37cc8 in abort () from /lib64/libc.so.6
#6  0x00007f3d30f2f546 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f3d30f2f5f2 in __assert_fail () from /lib64/libc.so.6
#8  0x0000000002fe6531 in Sql_cmd_insert_values::execute_inner (this=0x7f3c68126390, thd=0x7f3c68000be0) at ../../mysql-8.0.13/sql/sql_insert.cc:717
#9  0x0000000002adac0f in Sql_cmd_dml::execute (this=0x7f3c68126390, thd=0x7f3c68000be0) at ../../mysql-8.0.13/sql/sql_select.cc:595
#10 0x0000000002a7b4c0 in mysql_execute_command (thd=0x7f3c68000be0, first_level=true) at ../../mysql-8.0.13/sql/sql_parse.cc:3325
#11 0x0000000002a80acf in mysql_parse (thd=0x7f3c68000be0, parser_state=0x7f3d1de67360, force_primary_storage_engine=false) at ../../mysql-8.0.13/sql/sql_parse.cc:5041
#12 0x0000000002a76d24 in dispatch_command (thd=0x7f3c68000be0, com_data=0x7f3d1de67d10, command=COM_QUERY) at ../../mysql-8.0.13/sql/sql_parse.cc:1687
#13 0x0000000002a75434 in do_command (thd=0x7f3c68000be0) at ../../mysql-8.0.13/sql/sql_parse.cc:1260
#14 0x0000000002c08335 in handle_connection (arg=0x6ee3330) at ../../mysql-8.0.13/sql/conn_handler/connection_handler_per_thread.cc:308
#15 0x000000000448f062 in pfs_spawn_thread (arg=0x6ee2930) at ../../../mysql-8.0.13/storage/perfschema/pfs.cc:2836
#16 0x00007f3d32bdedf5 in start_thread () from /lib64/libpthread.so.0
#17 0x00007f3d30ff760d in clone () from /lib64/libc.so.6
(gdb)

- with release build
bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 8.0.13 MySQL Community Server - GPL

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show variables like 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin       | OFF   |
+---------------+-------+
1 row in set (0.00 sec)

mysql>    CREATE DATABASE a;
Query OK, 1 row affected (0.04 sec)

mysql>    USE a;
Database changed
mysql>    CREATE TABLE t1 (a datetime, b varchar(10) DEFAULT (localtimestamp()));
Query OK, 0 rows affected (0.01 sec)

mysql>    INSERT INTO t1(a) VALUES (now());
ERROR 1406 (22001): Data too long for column 'b' at row 1
mysql> set sql_mode='';
Query OK, 0 rows affected (0.00 sec)

mysql>    INSERT INTO t1(a) VALUES (now());
Query OK, 1 row affected, 1 warning (0.09 sec)
[4 Jan 10:04] jinming liao
Thank you, i think you are right, but the problem is that: DBUG_ASSERT(has_error == thd->get_stmt_da()->is_error()); will not be executed in release mode.
[11 Mar 13:50] Jon Olav Hauglid
Posted by developer:
 
The bug was introduced by:

commit 053f9c83ac470b6da66bce880b98ceb516a595be
Author: Catalin Besleaga <catalin.besleaga@oracle.com>
Date:   Thu Jul 5 18:43:25 2018 +0200

    WL#9418: Permit default value to be a function or expression
    
    Currently MySQL only permits a literal value as column default. This WL
    is removing this limitation by also allowing expressions to generate
    values as DEFAULT. With these changes the following syntax for
    defining/altering a column will be allowed:
    <column name> <column data type> DEFAULT (expression)
    
    This worklog reuses some of the infrastructure around Generated Columns
    and expands the range of functions that can be used as default
    expressions by also allowing the following non-deterministic functions:
    uuid, rand, statement_digest, statement_digest_text, curdate,
    current_date, curtime, current_time, current_timestamp, localtime,
    localtimestamp, now, sysdate, unix_timestamp, utc_date, utc_time,
    utc_timestamp, connection_id, database.
    Also all the deterministic functions that were previously allowed for
    Generated Columns are also allowed as default expressions.

And it was then fixed by:

commit 7f5d3d7dfe158555a3056ea21e0289c3c5ebe6e8 (HEAD)
Author: Catalin Besleaga <catalin.besleaga@oracle.com>
Date:   Tue Jul 31 02:19:06 2018 +0200

    WL#9418: follow up
    
    When binlogging is off default_as_expr.test asserts at
    DBUG_ASSERT(has_error == thd->get_stmt_da()->is_error());
    this happens because COPY_INFO::set_function_defaults does not
    return an error code in case something bad happens while executing a
    default expression.
    The patch makes the function return boolean to signal errors that might
    have happened and also rewrites
    ER_DEFAULT_VAL_GENERATED_NON_PRIOR error message to something less
    confusing.