MySQL Bugs: #88032: mysqld: Invalid default value for 'cached

Bug #88032	mysqld: Invalid default value for 'cached_time'
Submitted:	9 Oct 2017 17:18	Modified:	30 Oct 2017 17:38
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S2 (Serious)
Version:	8.0.3	OS:	CentOS (7)
Assigned to:		CPU Architecture:	Any
Tags:	crash

Description:
after upgrading MySQL 5.7.19 to 8.0.3-rc I see this crash:

2017-10-09T17:02:23.418156Z 1 [Note] [000000] InnoDB: 8.0.3 started; log sequence number 0
2017-10-09T17:02:23.510964Z 1 [Note] [000000] InnoDB: Waiting for purge to start
mysqld: Invalid default value for 'cached_time'
2017-10-09T17:02:23.651546Z 0 [ERROR] [003634] Data Dictionary initialization failed.
2017-10-09T17:02:23.651590Z 0 [ERROR] [003742] Aborting
2017-10-09T17:02:23.752004Z 0 [Note] [003743] Binlog end
2017-10-09T17:02:23.752959Z 0 [Note] [000000] InnoDB: Starting shutdown...
2017-10-09T17:02:26.161228Z 0 [Note] [000000] InnoDB: Deleting 2 new independent undo tablespaces that we just created.
2017-10-09T17:02:28.559787Z 0 [Note] [000000] InnoDB: Shutdown completed; log sequence number 46712712153825
2017-10-09T17:02:28.561986Z 0 [Note] [000000] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-10-09T17:02:28.576196Z 0 [NOTE] [001079] /usr/sbin/mysqld: Shutdown complete

17:02:28 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=805306368
read_buffer_size=4194304
max_used_connections=0
max_threads=10000
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 52116275 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x46000
/usr/sbin/mysqld(my_print_stacktrace+0x3d) [0x19e9afd]
/usr/sbin/mysqld(handle_fatal_signal+0x4d1) [0xebe601]
/lib64/libpthread.so.0(+0xf5e0) [0x7f4495af25e0]
/usr/sbin/mysqld(MY_LOCALE_ERRMSGS::lookup(int)+0x3c) [0xf6c34c]
/usr/sbin/mysqld(LogEvent::lookup(long long, ...)+0xa3) [0xa5d5c3]
/usr/sbin/mysqld() [0xa4f4db]
/usr/sbin/mysqld() [0xa4f9b5]
/usr/sbin/mysqld() [0xa55fdc]
/usr/sbin/mysqld(mysqld_main(int, char**)+0x163e) [0xa5a00e]
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f44944d0c05]
/usr/sbin/mysqld() [0xa47035]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
...

How to repeat:
upgrade from 5.7.19 to 8.0.3

configuration available on request.

note: in previous bugs "like this" it is usually due to old pages or settings in the data dictionary 
 or .frm files which aren't expected by the current code. This specific instance has been inplace upgraded since MySQL 5.0 so is likely to be susceptible to that.

Also note:

$ rpm -qi mysql-community-server
Name        : mysql-community-server
Version     : 8.0.3
Release     : 0.1.rc.el7
Architecture: x86_64
Install Date: Mon 09 Oct 2017 07:01:16 PM CEST
Group       : Applications/Databases
Size        : 1658632934
License     : Copyright (c) 2000, 2017, Oracle and/or its affiliates. All rights reserved. Under GPLv2 license as shown in the Description field.
Signature   : (none)
Source RPM  : mysql-community-8.0.3-0.1.rc.el7.src.rpm
Build Date  : Wed 06 Sep 2017 05:02:07 PM CEST
Build Host  : siv17.no.oracle.com
Relocations : (not relocatable)
Packager    : MySQL Release Engineering <mysql-build@oss.oracle.com>
Vendor      : Oracle and/or its affiliates
URL         : http://www.mysql.com/
Summary     : A very fast and reliable SQL database server
Description :
...

This may be from a slightly older version of 8.0.3 than the officially released version. The rpm -qi info should help clarify that as your rpm versioning makes it hard to see for sure.

Suggested fix:
Don't crash.

This has been filed internally already and devs are working on it still.

Bug 26188656 - SERVER CRASHES IN MY_LOCALE_ERRMSGS::LOOKUP DUE TO INCORRECT OPTION 
https://bugs.mysql.com/bug.php?id=86562

Thanks for clarification.

Hi Simon,

Note that we removed the option "information_schema_stats" and implemented a better and more intuitive option to handle this. We have introduced "information_schema_stats_expiry", see https://dev.mysql.com/doc/refman/8.0/en/statistics-table.html. Also see slide 36-37 on https://www.slideshare.net/StleDeraas/dd-and-atomic-ddl-pl17-dublin

The cause seems to be the explicit_defaults_for_timestamp=0 in my.cnf.

I can repeat the error on 8.0.3:

2017-10-10T14:12:23.158575Z 1 [Note] InnoDB: 8.0.3 started; log sequence number 0
mysqld: Invalid default value for 'cached_time'
2017-10-10T14:12:23.457979Z 0 [ERROR] Data Dictionary initialization failed.
2017-10-10T14:12:23.458195Z 0 [ERROR] Aborting

Starting up current debug build of 8.0 from git 
with --explicit-defaults-for-timestamp=0 asserts:

[Note] [000000] InnoDB: Waiting for purge to start
mysqld-debug: Invalid default value for 'cached_time'
Assertion failed: 0, file sql_class.cc, line 2918
abort() has been called
16:55:24 UTC - mysqld got exception 0x80000003 ;

mysqld-debug.exe!my_sigabrt_handler()[my_thr_init.cc:418]
  ucrtbased.dll!raise()
  ucrtbased.dll!abort()
  ucrtbased.dll!_get_wide_winmain_command_line()
  ucrtbased.dll!_get_wide_winmain_command_line()
  ucrtbased.dll!_get_wide_winmain_command_line()
  ucrtbased.dll!_wassert()
mysqld-debug.exe!THD::send_statement_status()[sql_class.cc:2918]
mysqld-debug.exe!Ed_connection::execute_direct()[sql_prepare.cc:3591]
mysqld-debug.exe!Ed_connection::execute_direct()[sql_prepare.cc:3560]
mysqld-debug.exe!execute_query()[bootstrapper.cc:77]
mysqld-debug.exe!`anonymous namespace'::create_tables()[bootstrapper.cc:220]
mysqld-debug.exe!dd::bootstrap::initialize_dictionary()[bootstrapper.cc:921]
mysqld-debug.exe!dd::upgrade::do_pre_checks_and_initialize_dd()[upgrade.cc:1230]
mysqld-debug.exe!handle_bootstrap()[bootstrap.cc:336]
mysqld-debug.exe!pfs_spawn_thread()[pfs.cc:2989]
mysqld-debug.exe!win_thread_start()[my_thread.cc:42]

Release build refuses to start and Aborts.  So something should be fixed.

--explicit-defaults-for-timestamp=0 is required in my configuration because I have upstream 5.7 servers. These boxes used to run 5.6 and before that 5.1 and 5.0 and there's been no way to make a migration path on running servers without (as far as I can see) potentially triggering incompatible changes between masters and slaves.

See: bug#74211

My feeling is that if I'm lucky and don't create tables with timestamps while changing these settings (on all servers in the replication chain) I may be ok but it's not clear to me. Certainly in bug#74211 I have received no suggestion on how migration may be completed on a running replication chain, and I have several I would like to change this setting on.

So the configuration is there as the default is now 1 and I need to be consistent with my upstream 5.7 master which uses the value of 0.

Hope this gives context to this setting.

Posted by developer:
 
Fixed in 8.0.4, 9.0.0.

An in-place upgrade from MySQL 5.7 failed if the server was started
with --explicit-defaults-for-timestamp=0 or a SET column had
duplicated values.