Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-381

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

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Fixed
    • 5.5.25, 5.3.7, 5.2.12, 5.1.62
    • 5.5.27
    • None
    • None
    • 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.

      Attachments

        1. data-and-logs.tar.gz
          1.53 MB
          Elena Stepanova
        2. ext4bug-minimal.c
          3 kB
          Kristian Nielsen

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-34671 File operations may miss fsync() on directories

          • Major - Major loss of function.
          • Open

          Activity

            People

              knielsen Kristian Nielsen
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.