MySQL Bugs: #41716: Backup Error when sending data (for table #1) to Default/Snapshot restore driver

Bug #41716	Backup Error when sending data (for table #1) to Default/Snapshot restore driver
Submitted:	23 Dec 2008 15:42	Modified:	3 Mar 2010 15:31
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S1 (Critical)
Version:	6.0-backup	OS:	Any
Assigned to:	Ingo Strüwing	CPU Architecture:	Any
Tags:	mdl

Description:
When attempting a RESTORE on a Falcon BACKUP, the following error occurs:

ERROR 1670 (HY000): Error when sending data (for table #1) to Snapshot restore driver

error log is not helpful:

081223 18:40:28 [Note] Restore: Starting restore process
081223 18:40:28 [Note] Restore: Restoring 1 database(s) `test`
081223 18:40:28 [Warning] Restore: The grant 'ALTER ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'CREATE ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'CREATE ROUTINE ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'CREATE TEMPORARY TABLES ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'CREATE VIEW ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'DELETE ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'DROP ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'EVENT ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'INDEX ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'INSERT ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'LOCK TABLES ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'REFERENCES ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'SELECT ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'SHOW VIEW ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'TRIGGER ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:28 [Warning] Restore: The grant 'UPDATE ON test.*' for the user ''@'%' was skipped because the user does not exist.
081223 18:40:47 [ERROR] Restore: Error when sending data (for table #1) to Snapshot restore driver
081223 18:40:49 [Note] Restore: Restore completed

How to repeat:
Restore the attached backup.

Backup for bug 41716

Attachment: bug41716-backup.zip (application/x-zip-compressed, text), 28.14 KiB.

Test case:

create table t1 (f1 integer) engine=falcon;
insert into t1 values (1);
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
backup database test to '/tmp/b1';
restore from '/tmp/b1' overwrite;

Table contains 1.048.576 rows before backup. After restore, zero rows.

Bug #42159 is set as duplicate of this bug here.

This error was also observed with Maria. Unfortunately, the error is not specific enough to know if it is the same issue.

Testcase:
1) patch like this:
=== modified file 'sql/backup/kernel.cc'
--- sql/backup/kernel.cc        2009-01-26 11:20:22 +0000
+++ sql/backup/kernel.cc        2009-02-03 16:41:46 +0000
@@ -1262,6 +1262,8 @@
   close_thread_tables(m_thd);                   // Never errors
   m_thd->main_da.reset_diagnostics_area();      // Never errors

+  fprintf(stderr, "insert into me please\n");
+  sleep(10);
   err= lock_tables_for_restore();               // logs errors
   if (err)
     DBUG_RETURN(fatal_error(err));

(i.e. a sleep when RESTORE is between create and lock).

2) run this test:
--disable_warnings
DROP DATABASE IF EXISTS mysqltest;
--error 0,1
--remove_file $MYSQLTEST_VARDIR/master-data/test.ba
--enable_warnings

CREATE DATABASE mysqltest;
USE mysqltest;
CREATE TABLE t1 (a int, b varchar(100), unique(a)) engine=memory;
insert into t1 values(1,"abc");

--replace_column 1 #
BACKUP DATABASE mysqltest TO 'test.ba';
DROP DATABASE mysqltest;
--replace_column 1 #
RESTORE FROM 'test.ba';
select * from t1;
flush tables;
select * from t1;

--echo
--echo connection default: cleanup
connection default;
drop database mysqltest;
--remove_file $MYSQLTEST_VARDIR/master-data/test.ba

With mtr. While it's in the sleep, open another connection and do:
insert into t1 values(1,"def");
Then RESTORE, when it wakes up, will print:
mysqltest: At line 16: query 'RESTORE FROM 'test.ba'' failed: 1670: Error when sending data (for table #1) to Default restore driver

I verified this with 6.0-maria but this is not involving Maria tables so I suspect it could exist in 6.0-main too.

I am attaching a patch (with debug sync points) and test which reproduces the problem with default and snapshot drivers.
The problem has been described already: after RESTORE has recreated the table empty and before it locks it (to fill it), a client manages to lock the table, and do a change to it (in the test, an INSERT). Later RESTORE writes rows to the table but one row conflicts (duplicate key) with what the INSERT client has inserted, RESTORE throws this error.
Example of error shown by the test:
mysqltest: At line 35: query 'reap' failed: 1670: Error when sending data (for table #1) to Snapshot restore driver
The test uses Falcon, change to MEMORY to provoke the bug with the default lock-based driver.

repeatable test

Attachment: bug41716.test (application/octet-stream, text), 1.04 KiB.

and here is the patch with sync points used by the test:
=== modified file 'sql/backup/kernel.cc'
--- sql/backup/kernel.cc        2009-02-03 07:48:09 +0000
+++ sql/backup/kernel.cc        2009-02-06 09:13:32 +0000
@@ -1324,10 +1324,14 @@
   close_thread_tables(m_thd);                   // Never errors
   m_thd->stmt_da->reset_diagnostics_area();     // Never errors

+  DEBUG_SYNC(m_thd, "before_restore_locks_tables");
+
   err= lock_tables_for_restore();               // logs errors
   if (err)
     DBUG_RETURN(fatal_error(err));

+  DEBUG_SYNC(m_thd, "after_restore_locks_tables");
+
   /*
    Here restore drivers are created to restore table data. Data is being
    (potentially) changed so we set m_data_changed flag.

Can be related to bug #41722

I could verify Guilhems analyze. So this bug is waiting for the same as Bug#40944 (Backup: crash after myisampack):

Waiting for the runtime team to provide an open_and_lock_tables(), which accepts name locks (exclusive mdl locks) on the tables.

Depends on Bug#42895 (Please implement a table open interface for name-locked tables)

To be more specific: We need a lock, that prevents other statements to access
the tables in restore even if they are not (yet) opened by RESTORE.
This is the intention for Bug#42895/WL#4844.

The patch for Bug#42895/Wl#4844 (Implement a locking scheme for RESTORE) solves this bug too. Queued to mysql-6.0-backup.

Pushed into 6.0.14-alpha (revid:ingo.struewing@sun.com-20100218152520-s4v1ld76bif06eqn) (version source revid:ingo.struewing@sun.com-20100119103538-wtp5alpz4p2jayl5) (merge vers: 6.0.14-alpha) (pib:16)

Due to improper locking, another connection could insert rows into a table being restored, thus causing duplicate key errors. The resulting error message was meaningless.

Noted in 6.0.14 changelog.