Bug #89515 ALTER TABLE Fails, then all subsequent schema operations fail
Submitted: 2 Feb 2018 23:19 Modified: 27 Feb 2018 23:47
Reporter: Eric Worrall Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:mysqld 5.7.21-0ubuntu0.16.04.1 OS:Ubuntu (Welcome to Ubuntu 16.04.3 LTS (GNU/Linux 4.4.0-1050-aws x86_64))
Assigned to: CPU Architecture:Any
Tags: 600s, ALTER TABLE, crash, reinstall, schema, Semaphore

[2 Feb 2018 23:19] Eric Worrall
Description:
If an alter table fails on a large database, on a table with several foreign key constraints, the server is completely unrecoverable. All subsequent schema operations, alter table, create table, drop database etc. fail. The client fails with "ERROR 2013 (HY000): Lost connection to MySQL server during query
", the server fails, usually with "[ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.", though sometimes with other errors. 

The only solution I've discovered so far is to completely purge the MySQL software and reinstall from scratch.

Any attempt to create a new table after this crash creates the .frm file but not the .ibd file before crashing. Creating a new database works, but any attempt to create a new table in the new database fails.

InnoDB: ###### Diagnostic info printed to the standard error stream
2018-02-02T22:46:21.862665Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2018-02-02 22:46:21 0x7f0522d5a700  InnoDB: Assertion failure in thread 139660035991296 in file ut0ut.cc line 942
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
22:46:21 UTC - mysqld got signal 6 ;
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=16777216
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 76385 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 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xe8f29b]
/usr/sbin/mysqld(handle_fatal_signal+0x489)[0x787029]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f053cb84390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f053bf3d428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f053bf3f02a]
/usr/sbin/mysqld[0x75ca3e]
/usr/sbin/mysqld(_ZN2ib5fatalD1Ev+0x145)[0x10573e5]
/usr/sbin/mysqld(srv_error_monitor_thread+0xe2d)[0xff46fd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f053cb7a6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f053c00f41d]
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.
2018-02-02T22:46:22.089310Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2018-02-02T22:46:22.089351Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2018-02-02T22:46:22.321706Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-02-02T22:46:22.323320Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.21-0ubuntu0.16.04.1) starting as process 7262 ...
2018-02-02T22:46:22.339289Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-02-02T22:46:22.339311Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-02-02T22:46:22.339315Z 0 [Note] InnoDB: Uses event mutexes
2018-02-02T22:46:22.339321Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-02-02T22:46:22.339325Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-02-02T22:46:22.339329Z 0 [Note] InnoDB: Using Linux native AIO
2018-02-02T22:46:22.339567Z 0 [Note] InnoDB: Number of pools: 1
2018-02-02T22:46:22.339675Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-02-02T22:46:22.341168Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-02-02T22:46:22.361145Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-02-02T22:46:22.362617Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-02-02T22:46:22.374319Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-02-02T22:46:22.375591Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 11754135738
2018-02-02T22:46:22.375604Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 11754138493
2018-02-02T22:46:22.376179Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-02-02T22:46:22.376190Z 0 [Note] InnoDB: Starting crash recovery.
2018-02-02T22:46:22.490391Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-02-02T22:46:22.490415Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-02-02T22:46:22.490459Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-02-02T22:46:22.547058Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-02-02T22:46:22.547717Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-02-02T22:46:22.547727Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-02-02T22:46:22.548320Z 0 [Note] InnoDB: Waiting for purge to start
2018-02-02T22:46:22.598488Z 0 [Note] InnoDB: 5.7.21 started; log sequence number 11754138493
2018-02-02T22:46:22.598511Z 0 [Note] InnoDB: !!! innodb_force_recovery is set to 1 !!!
2018-02-02T22:46:22.598948Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-02-02T22:46:22.603740Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-02-02T22:46:22.604855Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2018-02-02T22:46:22.604868Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2018-02-02T22:46:22.604877Z 0 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2018-02-02T22:46:22.604903Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2018-02-02T22:46:22.644175Z 0 [Note] Event Scheduler: Loaded 0 events
2018-02-02T22:46:22.644396Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.21-0ubuntu0.16.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
2018-02-02T22:46:23.110615Z 2 [Note] Access denied for user 'root'@'localhost' (using password: NO)
2018-02-02T22:46:23.605120Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180202 22:46:23

How to repeat:
1. Create an Amazon EC2 / Ubuntu t2.medium in Sydney.
2. Install apache2, php, perl, mysql-server
3. Create a database which contains large tables, with foreign key constraints between the tables.

Database size 4981012Kb, vanilla mysql.cnf file created by a fresh install using sudo apt install mysql-server.

4. Attempt an alter one of the tables to add new columns (no keys).
5. If the alter table fails, the database is now in an unrecoverable state.

Suggested fix:
Code fix - the database engine should be recoverable, even if the database has to be dropped and re-created.
[5 Feb 2018 17:20] MySQL Verification Team
Hi!

I have tried to replicate the scenario that you write about. I created several very large tables each with many foreign key relationships. I have tried to alter one table in the way that you describe, but it worked without a single problem. 

We can not verify a bug, unless we have a fully repeatable test case. That means we need dumps of all tables involved in the DDL, which means the target table. and the ones related to the target table. Then we require the exact DDL statement. Then, if we experience the same problems that you describe , we shall verify a bug and give it a very high priority.

We can not do anything without the data that I requested above.

Few additional notes. Do you use our binary, the one that is downloadable from dev.mysql.com or some other binary. If it is some other binary, I urge you to try our binary. Next, a crash can occur if number of required file handles is higher then the number of the available ones. Consult your OS manual on how to increase number of file descriptors.

One last issue. If you are unable to provide the above , consider running a debug binary of the server, which is also available on our site, which should produce a core file. Then, compress both binary and core file and upload it to this bug report, using the "Files" tab.

Please, do make sure you have provided all info that we requested, prior to any other comment you might have.

Thanks in advance.
[27 Feb 2018 23:47] Eric Worrall
Ubuntu upgrade appears to have resolved the issue, so it seems likely the problem was a defect in Ubuntu or a problem with Amazon's virtual machine environment rather than a problem with mysqld.

Ubuntu 16.04.3 LTS (GNU/Linux 4.4.0-1052-aws x86_64) /
mysqld  Ver 5.7.21-0ubuntu0.16.04.1 for Linux on x86_64 ((Ubuntu))

Thank you Sinisa Milivojevic for your response.
[28 Feb 2018 13:07] MySQL Verification Team
You are truly welcome .....