问题来源

• 公司数据库产品架构最近在做改变。测试人员在down掉一个分布式存储节点物理机后，MySQL默认会调度到其他节点。然而调度过程中发现MySQL无法启动，于是发来一张的截图：
  

问题分析

• 看到报错第一感觉就是MySQL的ibdata和redo有问题，于是google一圈也没有太大收获
• 于是乎就有了下面的复现的步骤

问题复现

①、确认已经有MySQL运行

[root@10-10-30-236 mysql]# ps -ef|grep mysqld
mysql     5000     1  0 Apr21 ?        00:07:53 /usr/local/mysql/bin/mysqld --defaults-file=/etc/mysql/my.cnf
root     32537 29366  0 15:57 pts/0    00:00:00 grep --color=auto mysqld

②、修改配置文件my.cnf部分参数

• 原my.cnf参数

port=3306
log-bin=/var/lib/mysql/archive/mysql-bin
log-error=/var/log/mysql/error.log

• 修改后参数

port=3307
log-bin=/var/lib/mysql/archive1/mysql-bin
log-error=/var/log/mysql/error1.log

③、创建目录并启动MySQL

# cp -r /var/lib/mysql/archive /var/lib/mysql/archive1
# cp -r /var/lib/mysql/redo /var/lib/mysql/redo1
# chown -R mysql:mysql /var/lib/mysql
# /opt/mysql-5.7.17-linux-glibc2.5-x86_64/bin/mysqld_safe --defaults-file=/opt/mysql-5.7.17-linux-glibc2.5-x86_64/my.cnf &

④、查看error.log信息

[root@10-10-30-236 mysql]# cat /var/log/mysql/error1.log
2019-04-23T07:41:46.298871Z 0 [Warning] The syntax '--metadata_locks_hash_instances' is deprecated and will be removed in a future release
2019-04-23T15:41:46.299104+08:00 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2019-04-23T15:41:46.299135+08:00 0 [Note] /opt/mysql-5.7.17-linux-glibc2.5-x86_64/bin/mysqld (mysqld 5.7.17-log) starting as process 32464 ...
2019-04-23T15:41:46.312984+08:00 0 [Warning] option 'innodb-buffer-pool-size': signed value 0 adjusted to 5242880
2019-04-23T15:41:46.313352+08:00 0 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
2019-04-23T15:41:46.313363+08:00 0 [Warning] InnoDB: Using innodb_file_format_max is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
2019-04-23T15:41:46.313409+08:00 0 [Note] InnoDB: PUNCH HOLE support not available
2019-04-23T15:41:46.313419+08:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-04-23T15:41:46.313422+08:00 0 [Note] InnoDB: Uses event mutexes
2019-04-23T15:41:46.313426+08:00 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2019-04-23T15:41:46.313429+08:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-04-23T15:41:46.313432+08:00 0 [Note] InnoDB: Using Linux native AIO
2019-04-23T15:41:46.317318+08:00 0 [Note] InnoDB: Number of pools: 1
2019-04-23T15:41:46.317444+08:00 0 [Note] InnoDB: Not using CPU crc32 instructions
2019-04-23T15:41:46.320971+08:00 0 [Note] InnoDB: Initializing buffer pool, total size = 5M, instances = 1, chunk size = 5M
2019-04-23T15:41:46.321480+08:00 0 [Note] InnoDB: Completed initialization of buffer pool
2019-04-23T15:41:46.322157+08:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-04-23T15:41:46.332282+08:00 0 [ERROR] InnoDB: Unable to lock /var/lib/mysql/data/innodb_ts/ibdata1 error: 11
2019-04-23T15:41:46.332298+08:00 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
2019-04-23T15:41:46.332302+08:00 0 [Note] InnoDB: Retrying to lock the first data file
2019-04-23T15:41:47.332427+08:00 0 [ERROR] InnoDB: Unable to lock /var/lib/mysql/data/innodb_ts/ibdata1 error: 11
2019-04-23T15:41:47.332471+08:00 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
...
2019-04-23T15:43:26.352934+08:00 0 [ERROR] InnoDB: Unable to lock /var/lib/mysql/data/innodb_ts/ibdata1 error: 11
2019-04-23T15:43:26.352988+08:00 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
2019-04-23T15:43:26.353008+08:00 0 [Note] InnoDB: Unable to open the first data file
2019-04-23T15:43:26.353054+08:00 0 [ERROR] InnoDB: Operating system error number 11 in a file operation.
2019-04-23T15:43:26.353078+08:00 0 [ERROR] InnoDB: Error number 11 means 'Resource temporarily unavailable'
2019-04-23T15:43:26.353092+08:00 0 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2019-04-23T15:43:26.353099+08:00 0 [ERROR] InnoDB: Cannot open datafile '/var/lib/mysql/data/innodb_ts/ibdata1'
2019-04-23T15:43:26.353105+08:00 0 [ERROR] InnoDB: Could not open or create the system tablespace. If you tried to add new data files to the system tablespace, and it failed here, you should now edit innodb_data_file_path in my.cnf back to what it was, and remove the new ibdata files InnoDB created in this failed attempt. InnoDB only wrote those files full of zeros, but did not yet use them in any way. But be careful: do not remove old data files which contain your precious data!
2019-04-23T15:43:26.353110+08:00 0 [ERROR] InnoDB: Plugin initialization aborted with error Cannot open a file
2019-04-23T15:43:26.953781+08:00 0 [ERROR] Plugin 'InnoDB' init function returned error.
2019-04-23T15:43:26.953831+08:00 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2019-04-23T15:43:26.953839+08:00 0 [ERROR] Failed to initialize plugins.
2019-04-23T15:43:26.953845+08:00 0 [ERROR] Aborting2019-04-23T15:43:26.953852+08:00 0 [Note] Binlog end
2019-04-23T15:43:26.953922+08:00 0 [Note] Shutting down plugin 'MyISAM'
2019-04-23T15:43:26.954354+08:00 0 [Note] /opt/mysql-5.7.17-linux-glibc2.5-x86_64/bin/mysqld: Shutdown complete

总结：

• 解决问题自然是停掉原来的MySQL进程再启动；或者新的MySQL重新定义redo和data目录；至于产品中为什么出现这个问题只能又开发同学排查了
• 有的时候google也不靠谱的情况下，只能根据自己的经验猜测来复现问题，从而解决问题了