[MDEV-381] Data inconsistency (missing rows, extra rows, different rows) between a recovered server and a restored binary log after an imitated HW crash - JIRA

Details

Type: Bug
Status: Closed
Priority: Critical
Resolution: Fixed
Affects Version/s: 5.5.25, 5.3.7, 5.2.12, 5.1.62
Fix Version/s: 5.5.27
Component/s: None
Labels:
None
Environment:
Windows 7 runs Oracle VirtualBox VM with Ubuntu 11.10 oneiric inside. The oneiric runs kvm VM based on vm-lucid-amd64-tarbake.qcow2.

Description

The test was run on 5.5-mdev232, and the data and logs are from there, but I observe the same problem on the main 5.5 tree also.

Test flow:

started kvm as

runvm \
--port=2201 \
--user=elenst \
--smp=1 \
--mem=2048 \
--startup-timeout=600 \
--shutdown-timeout=300 \
--cpu=qemu64 \
--base-image=<base image> \
<new image> \
bash

inside the VM, started MariaDB server as

5.5-mdev232/sql/mysqld \
--no-defaults \
--basedir=<basedir> \
--datadir=data \
--lc-messages-dir=<basedir>/sql/share \ 
--character-sets-dir=<basedir>/sql/share/charsets \
--core-file \
--max-allowed-packet=128Mb \
--port=19300 \
--socket=<socket file> \
--pid-file=<pidfile> \
--general-log \
--general-log-file=<general log> \
--sql-mode=no_engine_substitution \
--log-bin=master-bin \
--binlog-format=mixed \
--sync-binlog=1

created test tables (InnoDB), and for a few minutes ran one-thread DML flow (insert, update, delete, start transaction, commit, rollback)
Note: The thread sets SQL_SAFE_UPDATES=1 at the beginning;
while the flow was still running, killed the VM with SIGKILL;
stored a copy of the datadir and the binary log(s);

started server on the same datadir as

mysqld \
--no-defaults \
--basedir=<basedir> \
--datadir=<datadir> \
--lc-messages-dir=<basedir>/sql/share \
--character-sets-dir=<basedir>/sql/share/charsets \
--core-file \
--max-allowed-packet=128Mb \
--port=19300 \
--socket=<socket> \
--pid-file=<pidfile> \
--general-log \
--general-log-file=<general log> \
--sql-mode=no_engine_substitution \
--log-bin=master-bin \
--binlog-format=mixed \
--sync-binlog=1 \
--myisam-recover-options=FORCE \
--aria-recover=FORCE

ran mysqldump on the server;
shutdown the server gracefully;
started a new server on an empty datadir, with the same parameters;
fed the binary logs from the previous server to the new one;
ran mysqldump on the server;
sorted and compared two dumps

Here is the result of comparison (the first server is the recovered one, the second server is the one populated from the binlog):

@@ -30,7 +30,6 @@
 INSERT INTO `AA` VALUES (129,NULL,NULL,'0000-00-00','0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `AA` VALUES (130,66,NULL,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,NULL);
 INSERT INTO `AA` VALUES (132,NULL,NULL,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,'6');
-INSERT INTO `AA` VALUES (133,NULL,NULL,NULL,NULL,NULL,'00:00:56','0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `AA` VALUES (15,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `AA` VALUES (18,6,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,'7');
 INSERT INTO `AA` VALUES (20,NULL,NULL,NULL,'0000-00-00',NULL,'00:00:07',NULL,NULL,NULL,NULL);
@@ -103,7 +102,6 @@
 INSERT INTO `A` VALUES (93,9,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `A` VALUES (94,6,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `A` VALUES (96,NULL,NULL,NULL,NULL,'00:00:11',NULL,NULL,NULL,'1',NULL);
-INSERT INTO `A` VALUES (97,NULL,NULL,NULL,NULL,NULL,'00:00:09','0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `BB` VALUES (10,NULL,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `BB` VALUES (20,26,NULL,NULL,NULL,'00:00:36',NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `BB` VALUES (21,7,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL);
@@ -137,6 +135,7 @@
 INSERT INTO `BB` VALUES (72,NULL,14,NULL,NULL,NULL,NULL,NULL,NULL,'6',NULL);
 INSERT INTO `BB` VALUES (73,NULL,NULL,'0000-00-00',NULL,'00:00:06',NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `B` VALUES (104,6,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL);
+INSERT INTO `B` VALUES (110,NULL,NULL,'0000-00-00','0000-00-00',NULL,NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `B` VALUES (112,6,NULL,'0000-00-00',NULL,'00:00:06',NULL,NULL,NULL,NULL,NULL);
 INSERT INTO `B` VALUES (113,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,'5',NULL);
 INSERT INTO `B` VALUES (1,1,7,'1900-01-01','1900-01-01',NULL,NULL,'2001-11-04 19:07:55','2001-11-04 19:07:55','x','x');
@@ -204,7 +203,7 @@
 INSERT INTO `CC` VALUES (65,NULL,NULL,NULL,NULL,'00:00:00',NULL,'0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `CC` VALUES (68,NULL,NULL,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,'6');
 INSERT INTO `CC` VALUES (69,16,56,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL);
-INSERT INTO `CC` VALUES (6,NULL,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00','0000-00-00 00:00:00',NULL,NULL);
+INSERT INTO `CC` VALUES (6,NULL,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `CC` VALUES (71,NULL,NULL,NULL,NULL,'00:00:09','00:00:00',NULL,NULL,NULL,NULL);
 INSERT INTO `CC` VALUES (73,NULL,NULL,NULL,'0000-00-00',NULL,NULL,NULL,NULL,NULL,'1');
 INSERT INTO `CC` VALUES (75,76,NULL,NULL,NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,NULL,NULL);
@@ -345,13 +344,13 @@
 INSERT INTO `DD` VALUES (184,NULL,NULL,'0000-00-00',NULL,NULL,NULL,'0000-00-00 00:00:00',NULL,NULL,NULL);
 INSERT INTO `DD` VALUES (18,5,2,'2005-04-16','2005-04-16','09:21:51','09:21:51','2001-11-15 10:51:46','2001-11-15 10:51:46','v','v');
 INSERT INTO `DD` VALUES (185,NULL,NULL,'0000-00-00',NULL,NULL,'00:00:07',NULL,NULL,NULL,NULL);
-INSERT INTO `DD` VALUES (186,NULL,16,NULL,NULL,NULL,NULL,NULL,NULL,'6',NULL);
 INSERT INTO `DD` VALUES (19,163,103,'2007-05-12','2007-05-12','09:02:21','09:02:21','1900-01-01 00:00:00','1900-01-01 00:00:00','f','f');
 INSERT INTO `DD` VALUES (20,2,3,'2000-07-20','2000-07-20','22:40:03','22:40:03','2000-10-20 17:09:41','2000-10-20 17:09:41','q','q');
 INSERT INTO `DD` VALUES (22,0,2,'2004-08-04','2004-08-04',NULL,NULL,'2008-03-06 19:40:18','2008-03-06 19:40:18','a','a');
 INSERT INTO `DD` VALUES (23,9,7,'2002-06-25','2002-06-25','01:39:40','01:39:40','1900-01-01 00:00:00','0000-00-00 00:00:00','w','w');
 INSERT INTO `DD` VALUES (24,3,2,'2004-04-08','2004-04-08','18:14:11','18:14:11','2004-03-03 15:06:11','2004-03-03 15:06:11','e','e');
 INSERT INTO `DD` VALUES (25,1,2,'2004-12-20','2004-12-20','03:28:55','03:28:55','2009-06-03 03:14:33','2009-06-03 03:14:33',NULL,NULL);
+INSERT INTO `DD` VALUES (29,46,8,'2007-09-24','2007-09-24','00:00:00','00:00:00','2009-07-24 13:01:33','2009-07-24 13:01:33','k','6');
 INSERT INTO `DD` VALUES (30,9,4,'2000-05-07','2000-05-07','09:51:13','09:51:13','2005-04-14 03:38:00','2005-04-14 03:38:00',NULL,NULL);
 INSERT INTO `DD` VALUES (31,8,2,'2002-07-15','2002-07-15','11:25:28','11:25:28',NULL,NULL,'j','j');
 INSERT INTO `DD` VALUES (32,1,8,'2005-09-09','2005-09-09',NULL,NULL,'2002-07-16 03:25:43','2002-07-16 03:25:43','t','t');
@@ -518,6 +517,7 @@
 INSERT INTO `D` VALUES (67,7,8,NULL,NULL,'00:00:00','00:00:00','2003-12-17 21:47:57','2003-12-17 21:47:57',NULL,NULL);
 INSERT INTO `D` VALUES (68,2,5,'2007-02-07','2007-02-07','02:59:31','02:59:31',NULL,NULL,NULL,NULL);
 INSERT INTO `D` VALUES (69,1,8,'2005-01-22','2005-01-22','09:04:17','09:04:17','1900-01-01 00:00:00','1900-01-01 00:00:00','h','h');
+INSERT INTO `D` VALUES (6,NULL,16,NULL,NULL,NULL,NULL,NULL,NULL,NULL,'9');
 INSERT INTO `D` VALUES (70,9,2,'2006-04-25','2006-04-25','19:44:22','19:44:22',NULL,NULL,'k','k');
 INSERT INTO `D` VALUES (71,5,9,'2002-11-13','2002-11-13','00:00:00','00:00:00','2009-06-08 21:21:31','2009-06-08 21:21:31','k','k');
 INSERT INTO `D` VALUES (72,4,7,'2007-10-26','2007-10-26','00:00:00','00:00:00','2008-05-25 23:36:30','2008-05-25 23:36:30',NULL,NULL);

The last steps (recovery, feeding the binlog and comparison) can be reproduced with the provided dataset; the difference is still there.
Here is the recovery log:

120704 20:07:03 InnoDB: Initializing buffer pool, size = 128.0M
120704 20:07:04 InnoDB: Completed initialization of buffer pool
120704 20:07:04 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 2858763
120704 20:07:04  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 2877127
InnoDB: Transaction C1F was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is E00
120704 20:07:07  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96
 97 98 99 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 568642, file name ./master-bin.000001
InnoDB: Starting in background the rollback of uncommitted transactions
120704 20:07:08  InnoDB: Rollback of non-prepared transactions completed
120704 20:07:08  InnoDB: Waiting for the background threads to start
120704 20:07:09 Percona XtraDB (http://www.percona.com) 1.1.8-26.0 started; log sequence number 2877127
120704 20:07:12 [Note] Recovering after a crash using master-bin
120704 20:07:14 [Note] Starting crash recovery...
120704 20:07:14  InnoDB: Starting recovery for XA transactions...
120704 20:07:14  InnoDB: Transaction C1F in prepared state after recovery
120704 20:07:14  InnoDB: Transaction contains changes to 1 rows
120704 20:07:14  InnoDB: 1 transactions in prepared state after recovery
120704 20:07:14 [Note] Found 1 prepared transaction(s) in InnoDB
120704 20:07:14 [Note] rollback xid 'MySQLXid\1\0\0\0\0\0\0\0\334\30\0\0\0\0\0\0'
120704 20:07:14 [Note] Crash recovery finished.
120704 20:07:15 [Note] Event Scheduler: Loaded 0 events
120704 20:07:15 [Note] sql/mysqld: ready for connections.

Binlog reading is uneventful (no errors on the way).

The attached archive contains the following:

mysql.err - server error log from the server start and till the VM crash;
mysql.log - server general log from the server start and till the VM crash;
data/master-bin.index and data/master-bin.000001 - binary log from the server start and up to the VM crash;
data/*, data/*/* - usual datadir contents as of the moment of the VM crash.

Test tables are in the `test` schema.

Gliffy Diagrams

Attachments

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Attachments

data-and-logs.tar.gz
1.53 MB
2012-07-05 00:13
ext4bug-minimal.c
3 kB
2012-08-16 17:17

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Elena Stepanova added a comment - 2012-07-05 00:13

Attached file contains the datadir, binary log, general and error logs of the server after the VM crash

Show

Elena Stepanova added a comment - 2012-07-05 00:13 Attached file contains the datadir, binary log, general and error logs of the server after the VM crash

6 older comments

Hide

Permalink

Kristian Nielsen added a comment - 2012-09-03 13:10

I reported the ext3/ext4 bug upstream:

http://lkml.indiana.edu/hypermail/linux/kernel/1209.0/00437.html

Show

Kristian Nielsen added a comment - 2012-09-03 13:10 I reported the ext3/ext4 bug upstream: http://lkml.indiana.edu/hypermail/linux/kernel/1209.0/00437.html

Hide

Permalink

Kristian Nielsen added a comment - 2012-09-03 13:12

Patch is pushed to 5.3 and merged to 5.5

Show

Kristian Nielsen added a comment - 2012-09-03 13:12 Patch is pushed to 5.3 and merged to 5.5

Hide

Permalink

Elena Stepanova added a comment - 2012-09-03 16:09

I ran several single-thread and multi-thread tests on maria/5.3 revno 3573 and maria/5.5 revno 3520, both versions looked good so far (no failures). I'll run more later, but it will be out of scope of this bug report, I consider the workaround working for the provided test scenario.

Show

Elena Stepanova added a comment - 2012-09-03 16:09 I ran several single-thread and multi-thread tests on maria/5.3 revno 3573 and maria/5.5 revno 3520, both versions looked good so far (no failures). I'll run more later, but it will be out of scope of this bug report, I consider the workaround working for the provided test scenario.

Hide

Permalink

Kristian Nielsen added a comment - 2012-09-04 15:18

ext3 maintainer Jan Kara confirmed the bug in ext3/ext4, and proposed a patch:

http://www.spinics.net/lists/linux-ext4/msg33716.html
http://www.spinics.net/lists/linux-ext4/msg33717.html

Show

Kristian Nielsen added a comment - 2012-09-04 15:18 ext3 maintainer Jan Kara confirmed the bug in ext3/ext4, and proposed a patch: http://www.spinics.net/lists/linux-ext4/msg33716.html http://www.spinics.net/lists/linux-ext4/msg33717.html

Hide

Permalink

Kristian Nielsen added a comment - 2012-09-18 12:55

Looks like this will be fixed in older kernels back at least to 3.0:

https://patchwork.kernel.org/patch/1448361/

Show

Kristian Nielsen added a comment - 2012-09-18 12:55 Looks like this will be fixed in older kernels back at least to 3.0: https://patchwork.kernel.org/patch/1448361/

Data inconsistency (missing rows, extra rows, different rows) between a recovered server and a restored binary log after an imitated HW crash

Details

Description

Gliffy Diagrams

Attachments

Attachments

Activity

People

Dates

Time Tracking

Agile