Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Not a Bug
-
10.1.21
-
None
-
Linux gimli 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u1 (2016-09-03) x86_64 GNU/Linux
Description
TLDR: The debian package install script is causing me hours of downtime.
The problem started when we upgraded from 10.1.20 to 10.1.21
After 2 hours the upgrade seems to have failed with this message:
Setting up mariadb-server-10.1 (10.1.21+maria-1jessie) ...
|
Job for mariadb.service failed. See 'systemctl status mariadb.service' and 'journalctl -xn' for details.
|
invoke-rc.d: initscript mysql, action "start" failed.
|
dpkg: error processing package mariadb-server-10.1 (--configure):
|
subprocess installed post-installation script returned error exit status 1
|
dpkg: dependency problems prevent configuration of mariadb-server:
|
mariadb-server depends on mariadb-server-10.1 (= 10.1.21+maria-1jessie); however:
|
Package mariadb-server-10.1 is not configured yet.
|
|
|
dpkg: error processing package mariadb-server (--configure):
|
dependency problems - leaving unconfigured
|
After that error i was able to start mariadb and it worked fine..
Fast forward to today ..
i run apt-get upgrade and apt-get decides to "set up" mariadb, (probably because it was left "unconfigured" after yesterdays upgrade..
Setting up mariadb-server-10.1 (10.1.21+maria-1~jessie) ...
|
The script then proceeds to stop my mariadb,, stopping my mariadb takes 1 hour roughly,, this is 1 hour of unscheduled downtime...
here's some logs from today havoc..
017-01-31 11:37:17 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:18 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:18 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:19 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:19 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:20 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:20 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:21 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:21 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:22 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:22 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:23 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:23 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:23 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:37:24 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:24 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:25 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:25 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:26 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:26 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:27 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:27 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:28 139690684753856 [ERROR] InnoDB: Unable to lock ./ibdata1, error: 11
|
2017-01-31 11:37:28 139690684753856 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB data or log files.
|
2017-01-31 11:37:28 139690684753856 [Note] InnoDB: Unable to open the first data file
|
2017-01-31 11:37:28 7f0c45a4a7c0 InnoDB: Operating system error number 11 in a file operation.
|
InnoDB: Error number 11 means 'Resource temporarily unavailable'.
|
InnoDB: Some operating system error numbers are described at
|
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
|
2017-01-31 11:37:28 139690684753856 [ERROR] InnoDB: Can't open './ibdata1'
|
2017-01-31 11:37:28 139690684753856 [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!
|
2017-01-31 11:37:28 139690684753856 [ERROR] Plugin 'InnoDB' init function returned error.
|
2017-01-31 11:37:28 139690684753856 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
|
2017-01-31 11:37:28 139690684753856 [ERROR] Unknown/unsupported storage engine: InnoDB
|
2017-01-31 11:37:28 139690684753856 [ERROR] Aborting
|
|
|
2017-01-31 11:38:24 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:39:24 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:40:24 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:41:24 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:42:24 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:43:25 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:44:25 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:45:25 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:46:25 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
2017-01-31 11:47:25 139813703478016 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
|
|
notice how it's shutting down "Waiting for page_cleaner to finish flushing of buffer pool" .. yet debian tries to start new instances at the same time.. because the script is too stupid to realize it's in the process of shutting down ....
PLEASE make the install script understand that some databases takes hours to shut down and prompt for shutdown before just doing it!!
You can read about yesterdays upgrade havoc in the comments here https://github.com/MariaDB/server/commit/ab1e6fefd869242d962cb91a006f37bb9ad534a7