Bug #73366 mysqlserverclone does not detect full disk error in Linux
Submitted: 23 Jul 2014 13:23 Modified: 5 Sep 2014 5:18
Reporter: Shahriyar Rzayev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Utilities Severity:S1 (Critical)
Version:1.4.3 OS:Linux (CentOS 6.5)
Assigned to: CPU Architecture:Any
Tags: diskfull, mysqlserverclone

[23 Jul 2014 13:23] Shahriyar Rzayev
Description:
Dear experts,

i tried to use mysqlserveclone as :

-bash-4.1$ mysqlserverclone --server=root@localhost --new-data=/usr/local/mysql/data2 --new-port=3307 --root-password=12345 --mysqld=--log-bin=mysql-bin
# Cloning the MySQL server running on localhost.
# Creating new data directory...
# Configuring new instance...
# Locating mysql tools...
# Setting up empty database and mysql tables...
ERROR: Failed to kill process with pid '3238'

These error described nothing related to my issue.

It was clear only after adding -vvv option:

-bash-4.1$ rm -rf data2
-bash-4.1$ mysqlserverclone --server=root@localhost --new-data=/usr/local/mysql/data2 --new-port=3307 --root-password=12345 --mysqld=--log-bin=mysql-bin -vvv
# Cloning the MySQL server running on localhost.
# Creating new data directory...
# Configuring new instance...
# Locating mysql tools...
# Location of files:
#                       mysqld: /usr/local/mysql/bin/mysqld
#                   mysqladmin: /usr/local/mysql/bin/mysqladmin
#      mysql_system_tables.sql: /usr/local/mysql/share/mysql_system_tables.sql
# mysql_system_tables_data.sql: /usr/local/mysql/share/mysql_system_tables_data.sql
# mysql_test_data_timezone.sql: /usr/local/mysql/share/mysql_test_data_timezone.sql
#         fill_help_tables.sql: /usr/local/mysql/share/fill_help_tables.sql
# Setting up empty database and mysql tables...
2014-07-23 09:14:57 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-07-23 09:14:57 3258 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2014-07-23 09:14:57 3258 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

2014-07-23 09:14:57 3258 [Note] Plugin 'FEDERATED' is disabled.
2014-07-23 09:14:57 3258 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-07-23 09:14:57 7febe3f62720 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2014-07-23 09:14:57 7febe3f62720 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2014-07-23 09:14:57 3258 [Note] InnoDB: The InnoDB memory heap is disabled
2014-07-23 09:14:57 3258 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-07-23 09:14:57 3258 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-07-23 09:14:57 3258 [Note] InnoDB: Not using CPU crc32 instructions
2014-07-23 09:14:57 3258 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-07-23 09:14:57 3258 [Note] InnoDB: Completed initialization of buffer pool
2014-07-23 09:14:57 3258 [Note] InnoDB: The first specified data file ./ibdata1 did not exist: a new database to be created!
2014-07-23 09:14:57 3258 [Note] InnoDB: Setting file ./ibdata1 size to 12 MB
2014-07-23 09:14:57 3258 [Note] InnoDB: Database physically writes the file full: wait...
2014-07-23 09:14:57 3258 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2014-07-23 09:14:57 7febe3f62720 InnoDB: Error: Write to file ./ib_logfile101 failed at offset 17825792.
InnoDB: 1048576 bytes should have been written, only 974848 were written.
InnoDB: Operating system error number 2.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 2 means 'No such file or directory'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2014-07-23 09:14:57 3258 [ERROR] InnoDB: Cannot set log file ./ib_logfile101 to size 48 MB
2014-07-23 09:14:57 3258 [ERROR] Plugin 'InnoDB' init function returned error.
2014-07-23 09:14:57 3258 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2014-07-23 09:14:57 3258 [ERROR] Unknown/unsupported storage engine: InnoDB
2014-07-23 09:14:57 3258 [ERROR] Aborting

2014-07-23 09:14:57 3258 [Note] Binlog end
2014-07-23 09:14:57 3258 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

ERROR: Failed to kill process with pid '3258'

So as described there was a full disk problem:
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.

It takes several time to figure out exact problem.

How to repeat:
Create a condition with full disk error and use mysqlserverclone as described.

Suggested fix:
Maybe checking available space before cloning MySQL will be great.
[28 Jul 2014 8:09] MySQL Verification Team
Hello Shahriyar,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[28 Jul 2014 8:12] MySQL Verification Team
//How to repeat
// Just 6M+ left on /tmp/

[root@cluster-repo tmp]# df -h /tmp/
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/vg_clusterrepo-lv_root
                       11G   11G  6.8M 100% /

// Started cloning existing server

[ushastry@cluster-repo ~]$ mysqlserverclone --help
MySQL Utilities mysqlserverclone version 1.4.3 (part of MySQL Workbench Distribution 6.0.0)

[ushastry@cluster-repo ~]$ mysqlserverclone --server=root@localhost --new-data=/tmp/master2 --new-port=3307 --root-password=12345 --mysqld=--log-bin=mysql-bin --mysqld=--user=mysql --delete-data
# Cloning the MySQL server running on localhost.
# Creating new data directory...
# Configuring new instance...
# Locating mysql tools...
# Setting up empty database and mysql tables...
ERROR: Failed to kill process with pid '9366'

// With verbose

[ushastry@cluster-repo ~]$ mysqlserverclone --server=root@localhost --new-data=/tmp/master2 --new-port=3307 --root-password=12345 --mysqld=--log-bin=mysql-bin --mysqld=--user=mysql -vvv --delete-data
# Cloning the MySQL server running on localhost.
# Creating new data directory...
# Configuring new instance...
# Locating mysql tools...
# Location of files:
#                       mysqld: /data/ushastry/server/mysql-advanced-5.6.21/bin/mysqld
#                   mysqladmin: /data/ushastry/server/mysql-advanced-5.6.21/bin/mysqladmin
#      mysql_system_tables.sql: /data/ushastry/server/mysql-advanced-5.6.21/share/mysql_system_tables.sql
# mysql_system_tables_data.sql: /data/ushastry/server/mysql-advanced-5.6.21/share/mysql_system_tables_data.sql
# mysql_test_data_timezone.sql: /data/ushastry/server/mysql-advanced-5.6.21/share/mysql_test_data_timezone.sql
#         fill_help_tables.sql: /data/ushastry/server/mysql-advanced-5.6.21/share/fill_help_tables.sql
# Setting up empty database and mysql tables...
2014-07-30 04:25:50 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-07-30 04:25:50 9348 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)

2014-07-30 04:25:50 9348 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

2014-07-30 04:25:50 9348 [Note] Plugin 'FEDERATED' is disabled.
2014-07-30 04:25:50 9348 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-07-30 04:25:50 9348 [Note] InnoDB: The InnoDB memory heap is disabled
2014-07-30 04:25:50 9348 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-07-30 04:25:50 9348 [Note] InnoDB: Memory barrier is not used
2014-07-30 04:25:50 9348 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-07-30 04:25:50 9348 [Note] InnoDB: Using Linux native AIO
2014-07-30 04:25:50 9348 [Note] InnoDB: Not using CPU crc32 instructions
2014-07-30 04:25:50 9348 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-07-30 04:25:50 9348 [Note] InnoDB: Completed initialization of buffer pool
2014-07-30 04:25:50 9348 [Note] InnoDB: The first specified data file ./ibdata1 did not exist: a new database to be created!
2014-07-30 04:25:50 9348 [Note] InnoDB: Setting file ./ibdata1 size to 12 MB
2014-07-30 04:25:50 9348 [Note] InnoDB: Database physically writes the file full: wait...
2014-07-30 04:25:50 7fb8a419e720 InnoDB: Error: Write to file ./ibdata1 failed at offset 6291456.
InnoDB: 1048576 bytes should have been written, only 733184 were written.
InnoDB: Operating system error number 2.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 2 means 'No such file or directory'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2014-07-30 04:25:50 9348 [ERROR] InnoDB: Error in creating ./ibdata1: probably out of disk space
2014-07-30 04:25:50 9348 [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!
2014-07-30 04:25:50 9348 [ERROR] Plugin 'InnoDB' init function returned error.
2014-07-30 04:25:50 9348 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2014-07-30 04:25:50 9348 [ERROR] Unknown/unsupported storage engine: InnoDB
2014-07-30 04:25:50 9348 [ERROR] Aborting

2014-07-30 04:25:50 9348 [Note] Binlog end
2014-07-30 04:25:50 9348 [Note] /data/ushastry/server/mysql-advanced-5.6.21/bin/mysqld: Shutdown complete

ERROR: Failed to kill process with pid '9348'
[5 Sep 2014 5:18] Philip Olson
Fixed as of the upcoming MySQL Utilities 1.5.2 release, and here's the changelog entry:

The "mysqlserverclone" utility did not check for a low amount of free
space before it created a new instance of the server. It now errors out if
120+ MB of free space is unavailable, but this check can be ignored by
also passing in the "--force" option. 

Additionally, the error handling for failed new data directory creation 
was improved to show additional details about the failure.

Thank you for the bug report.