MySQL Bugs: #69907: Error(1030): Got error -1 from storage engine

Bug #69907	Error(1030): Got error -1 from storage engine
Submitted:	2 Aug 2013 8:56	Modified:	20 Dec 2013 19:24
Reporter:	Shahriyar Rzayev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.6.12, 5.6.13	OS:	Linux (Centos 6.4)
Assigned to:		CPU Architecture:	Any

Description:
This report is primarily related to my previous bug:

http://bugs.mysql.com/bug.php?id=69898

All problems start after with using:
mysqlreplicate --master=root:12345@localhost:3306 --slave=remote:12345@192.168.1.106 --rpl-user=repl:12345@192.168.1.106 -vv

In fact replication did not setup properly and indeed it is not connected to master and not functional.
After using this utility MySQL server did not startet and i reported it immediately (http://bugs.mysql.com/bug.php?id=69898)

After reading carefully error log decided to start MySQL with innodb_force_recovery=3.
It started successfully with some errors. Here is error log:

InnoDB: 4 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 8 row operations to undo
InnoDB: Trx id counter is 3840
2013-08-02 12:07:13 4195 [Note] InnoDB: 5.6.12 started; log sequence number 1689337
2013-08-02 12:07:13 4195 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!
2013-08-02 12:07:14 4195 [Note] Server hostname (bind-address): '*'; port: 3306
2013-08-02 12:07:14 4195 [Note] IPv6 is available.
2013-08-02 12:07:14 4195 [Note]   - '::' resolves to '::';
2013-08-02 12:07:14 4195 [Note] Server socket created on IP: '::'.
2013-08-02 12:07:14 4195 [Warning] 'proxies_priv' entry '@ root@localhost.localdomain' ignored in --skip-name-resolve mode.
InnoDB: A new raw disk partition was initialized or
InnoDB: innodb_force_recovery is on: we do not allow
InnoDB: database modifications by the user. Shut down
InnoDB: mysqld and edit my.cnf so that newraw is replaced
InnoDB: with raw, and innodb_force_... is removed.
2013-08-02 12:07:14 4195 [ERROR] Error writing master configuration.
2013-08-02 12:07:14 4195 [ERROR] Error reading master configuration.
InnoDB: A new raw disk partition was initialized or
InnoDB: innodb_force_recovery is on: we do not allow
InnoDB: database modifications by the user. Shut down
InnoDB: mysqld and edit my.cnf so that newraw is replaced
InnoDB: with raw, and innodb_force_... is removed.
2013-08-02 12:07:14 4195 [ERROR] Error writing relay log configuration.
2013-08-02 12:07:14 4195 [ERROR] Error reading relay log configuration.
2013-08-02 12:07:14 4195 [ERROR] Failed to initialize the master info structure
2013-08-02 12:07:14 4195 [Note] Check error log for additional messages. You will not be able to start replication until the issue is resolved and the server restarted.
2013-08-02 12:07:14 4195 [Note] Event Scheduler: Loaded 0 events
2013-08-02 12:07:14 4195 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.12-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

Now i can connect to MySQL. Just want to reset slave :

mysql> reset slave;
ERROR 1030 (HY000): Got error -1 from storage engine

Got this interesting error. Googled for "-1" result is nothing to read.

All errors at this time:

mysql> show errors;
+-------+------+-----------------------------------------------------------------------------------------------------+
| Level | Code | Message                                                                                             |
+-------+------+-----------------------------------------------------------------------------------------------------+
| Error | 1030 | Got error -1 from storage engine                                                                    |
| Error | 1030 | Got error -1 from storage engine                                                                    |
| Error | 1201 | Could not initialize master info structure; more error messages can be found in the MySQL error log |
+-------+------+-----------------------------------------------------------------------------------------------------+
3 rows in set (0.30 sec)

As mentioned in error log:
InnoDB: A new raw disk partition was initialized or
InnoDB: innodb_force_recovery is on: we do not allow
InnoDB: database modifications by the user. Shut down
InnoDB: mysqld and edit my.cnf so that newraw is replaced
InnoDB: with raw, and innodb_force_... is removed.

Now i commented out innodb_force_recovery=3 and want shut down MySQL. Unsuccessfully and it takes a long time that i just kill all processes:

[root@dhcppc0 mysql]# time service mysql stop
Shutting down MySQL.....................................................................................................................................................................................................................^C

real	3m34.089s
user	0m0.508s
sys	0m0.633s

[root@dhcppc0 data]# ps ax | grep mysql
 3400 pts/0    S      0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/dhcppc0.pid
 4195 pts/0    Sl     0:08 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/lib/mysql/dhcppc0.err --open-files-limit=65535 --pid-file=/var/lib/mysql/dhcppc0.pid --socket=/var/lib/mysql/mysql.sock
 6079 pts/1    S+     0:00 grep mysql

Killed. And it is started:

[root@dhcppc0 data]# time service mysql start
Starting MySQL SUCCESS! 

real	0m0.172s
user	0m0.027s
sys	0m0.029s

But i cant establish connection:

[root@dhcppc0 data]# mysql -u root -p
Enter password: 
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/lib/mysql/mysql.sock' (2)

Checked processes and in fact MySQL not started but i get a SUCCESS message :)

[root@dhcppc0 mysql]# ps ax | grep mysql
 7857 pts/0    S+     0:00 grep mysql

Looked at error log again and saw same errors from previous bug report:

http://bugs.mysql.com/bug.php?id=69898

So even innodb_force_recovery doesn't work. What we can do now?

How to repeat:
Fresh installed Centos 6.4 on Virtualbox with MySQL 5.6.12.
Tried to setup replication with mysqlreplicate utility.
After unsuccessful attempt started getting errors from "slave"(actually it doesn't functionally/properly works)

To get some error from mysqlreplicate just give wrong --rpl-user and it will prompt that cant create a replication.
Then restart your Slave which i installed in virtualbox.
It will not restart. Arguing with errors in :
http://bugs.mysql.com/bug.php?id=69898

Suggested fix:
Cant suggest anything waiting for help.

Probably you can not reset slave as in forced recovery mode you can not modify data in InnoDB tables. Now, to check why any tables may be involved, please, send the output of:

show variables like '%info%';

from this server. I wonder what are the values for master_info_repository and/or relay_log_info_repository in case of both these bugs. I suspect TABLE...

mysql> show variables like '%info%';
+---------------------------+----------------+
| Variable_name             | Value          |
+---------------------------+----------------+
| master_info_repository    | TABLE          |
| relay_log_info_file       | relay-log.info |
| relay_log_info_repository | TABLE          |
| sync_master_info          | 10000          |
| sync_relay_log_info       | 10000          |
+---------------------------+----------------+
5 rows in set (0.00 sec)

And please provide information if exists about "-1" error from storage engine.

As i stated when i submit this report it is primarily related to my previous BUG report:
http://bugs.mysql.com/bug.php?id=69898

It is already VERIFIED as Critical. And i want to inform you.
You can repeat all scenario i have uploaded all files and informations for repeating this crash.

I separate this BUG report because of logical difference. After crash i just want to use innodb_force_recovery. So this bug report is related to recovery stage with nowhere documented interesting error: Error(1030): Got error -1 from storage engine

Thanks.

related problem: http://bugs.mysql.com/bug.php?id=69892

Hello Shahriyar,

Thank you for the bug report. 
Verified as described.

imho - Bug #69898 and #69907 are inter related but not the same.. one leads to crash issue, in attempt to recover it ended up with "ERROR 1030 (HY000): Got error -1 from storage engine"..

Thanks,
Umesh

Same steps as Shane explained in Bug #69898 	
------------------------------------------------

bin/mysqld_safe --no-defaults --server_id=1 --log_bin --binlog_format=row --log_slave_updates=1 --read_only=1 --gtid-mode=on --enforce-gtid-consistency=true --master-info-repository=TABLE --relay-log-info-repository=TABLE --slave-parallel-workers=2 --basedir=/home/ushastry/mybuilds/mysql-5.6.13/ --datadir=/tmp/69898 --user=mysql &

Run:
-----
stop slave;
set session autocommit=0;
change master to master_host='127.0.0.1', master_port=3306, master_user='root', master_password='', MASTER_AUTO_POSITION=1;

Restart server and repeat the above again... i.e

Run:
-----
stop slave;
set session autocommit=0;
change master to master_host='127.0.0.1', master_port=3306, master_user='root', master_password='', MASTER_AUTO_POSITION=1;

Restart server and repeat the above again but with extra parameter --innodb_force_recovery=3

bin/mysqld_safe --no-defaults --server_id=1 --log_bin --binlog_format=row --log_slave_updates=1 --read_only=1 --gtid-mode=on --enforce-gtid-consistency=true --master-info-repository=TABLE --relay-log-info-repository=TABLE --slave-parallel-workers=2 --basedir=/home/ushastry/mybuilds/mysql-5.6.13/ --datadir=/tmp/69898 --user=mysql --innodb_force_recovery=3 &

Run:
-----
stop slave;
set session autocommit=0;
change master to master_host='127.0.0.1', master_port=3306, master_user='root', master_password='', MASTER_AUTO_POSITION=1;

After the last "change master" - you would notice "ERROR 1030 (HY000): Got error -1 from storage engine"

Yes i agree that there are not same,
and thats why i separate this BUGs and reported sequentally.

Thanks for verifing my effort.

Any suggestions? how i can start my server at this moment?

I would vote this Bug#69907 and Bug#69914 to be duplicates of Bug#69898.
See my analysis and explanation in Bug#69898.
The implementation of CHANGE MASTER is breaking the rules.

I posted a preliminary patch in Bug#69898 that would change InnoDB recovery in a way that might allow crash recovery from this breakage. If we included that patch, it would have to be controlled by some configuration option.

Fixed as of 5.6.16, 5.7.4, and here's the changelog entry:

Attempting to reset a replication slave while "innodb_force_recovery" is
greater than "0" would return a cryptic error message: "ERROR(1030) HY000:
Got error -1 from storage engine". The error message has been changed to:
"ERROR HY000: Operation not allowed when innodb_force_recovery > 0".
Replication options such as "--relay-log-info-repository=TABLE" and
"--master-info-repository=TABLE" store information in tables in "InnoDB".
When "innodb_force_recovery" is greater than 0, replication tables cannot
be updated which may cause replication administration commands to fail.

Thank you for the bug report.

5.6$ bzr log -r 5706
------------------------------------------------------------
revno: 5706
committer: Aditya A <aditya.a@oracle.com>
branch nick: mysql-5.6
timestamp: Fri 2013-12-20 11:22:30 +0530
message:
  Bug#17287443	ERROR(1030): GOT ERROR -1 FROM STORAGE ENGINE
  
  PROBLEM
  -------
  When we try to do DML operations in innodb 
  force recovery mode.we get a cryptic error
  message.
  ERROR(1030): GOT ERROR -1 FROM STORAGE ENGINE
  
  FIX
  ---
  Introduced a new error ER_INNODB_FORCE_RECOVERY 
  which will print proper error message. 
  
  [Approved by Kevin and Krunal #rb4095 and rb#4137]