epermana / tungsten-replicator

Automatically exported from code.google.com/p/tungsten-replicator
1 stars 0 forks source link

Consistency checking fails on MyISAM table with unequally ordered data #806

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago
What steps will reproduce the problem?

./trepct check db.table

What is the expected output?

Success on slaves that have the same data as the master.

What do you see instead?

INFO   | jvm 1    | 2014/01/23 11:22:00 | 
com.continuent.tungsten.replicator.consistency.ConsistencyException: 
Consistency check failed on table 'db.table' id: 694, offset: -1, limit: -1, 
method: 'md5' failed
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.consistencyCheck(JdbcAppl
ier.java:346)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.apply(JdbcApplier.java:13
92)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.ApplierWrapper.apply(ApplierWrapper.j
ava:101)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.apply(SingleTh
readStageTask.java:706)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.runTask(Single
ThreadStageTask.java:484)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.run(SingleThre
adStageTask.java:169)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,220 [prod - 
q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Performing emergency rollback 
of applied changes
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,220 [prod - 
q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Dispatching error event: 
Stage task failed: stage=q-to-dbms seqno=460287198 fragno=0
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,243 [prod - 
q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Terminating processing for 
stage task thread
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,243 [prod - 
q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Last successfully processed 
event prior to termination: seqno=460287198 
eventid=mysql-bin.000402:0000000718984673;0
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,243 [prod - 
q-to-dbms-0] INFO  pipeline.SingleThreadStageTask Task event count: 686348
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,259 [prod - 
pool-2-thread-1] ERROR management.OpenReplicatorManager Received error 
notification, shutting down services :
INFO   | jvm 1    | 2014/01/23 11:22:00 | Stage task failed: stage=q-to-dbms 
seqno=460287198 fragno=0
INFO   | jvm 1    | 2014/01/23 11:22:00 | 
com.continuent.tungsten.replicator.consistency.ConsistencyException: 
Consistency check failed on table 'db.table' id: 694, offset: -1, limit: -1, 
method: 'md5' failed
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.consistencyCheck(JdbcAppl
ier.java:346)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.apply(JdbcApplier.java:13
92)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.applier.ApplierWrapper.apply(ApplierWrapper.j
ava:101)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.apply(SingleTh
readStageTask.java:706)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.runTask(Single
ThreadStageTask.java:484)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.run(SingleThre
adStageTask.java:169)
INFO   | jvm 1    | 2014/01/23 11:22:00 |       at 
java.lang.Thread.run(Thread.java:662)
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,260 [prod - 
pool-2-thread-1] WARN  management.OpenReplicatorManager Performing emergency 
service shutdown
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,260 [prod - 
pool-2-thread-1] INFO  pipeline.Pipeline Shutting down pipeline: slave
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
remote-to-thl-0] INFO  thl.RemoteTHLExtractor Connector read failed after 
shutdown; not attempting to reconnect
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
remote-to-thl-0] INFO  pipeline.SingleThreadStageTask Performing rollback of 
possible partial transaction: seqno=(unavailable)
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
remote-to-thl-0] INFO  pipeline.SingleThreadStageTask Terminating processing 
for stage task thread
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
remote-to-thl-0] INFO  pipeline.SingleThreadStageTask Last successfully 
processed event prior to termination: seqno=460287201 
eventid=mysql-bin.000402:0000000718987903;0
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
remote-to-thl-0] INFO  pipeline.SingleThreadStageTask Task event count: 686659
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,305 [prod - 
thl-to-q-0] WARN  pipeline.SingleThreadStageTask Received unexpected interrupt 
in stage task: thl-to-q
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,306 [prod - 
thl-to-q-0] INFO  pipeline.SingleThreadStageTask Terminating processing for 
stage task thread
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,306 [prod - 
thl-to-q-0] INFO  pipeline.SingleThreadStageTask Last successfully processed 
event prior to termination: seqno=460287201 
eventid=mysql-bin.000402:0000000718987903;0
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,306 [prod - 
thl-to-q-0] INFO  pipeline.SingleThreadStageTask Task event count: 686662
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,306 [prod - 
pool-2-thread-1] INFO  pipeline.Pipeline Releasing pipeline: slave
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,306 [prod - 
pool-2-thread-1] INFO  pipeline.StageTaskGroup Releasing tasks for stage: 
remote-to-thl
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,307 [prod - 
pool-2-thread-1] INFO  pipeline.StageTaskGroup Releasing tasks for stage: 
thl-to-q
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,307 [prod - 
pool-2-thread-1] INFO  pipeline.StageTaskGroup Releasing tasks for stage: 
q-to-dbms
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,308 [prod - 
pool-2-thread-1] INFO  thl.Server Stopping server thread
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,309 [prod - THL 
Server [thl:0.0.0.0:2112]] INFO  thl.Server Server thread cancelled
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,309 [prod - THL 
Server [thl:0.0.0.0:2112]] INFO  thl.Server Closing connector handlers for THL 
Server: store=thl
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,309 [prod - THL 
Server [thl:0.0.0.0:2112]] INFO  thl.Server Closing socket: store=thl 
host=/0.0.0.0:2112 port=2112
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,309 [prod - THL 
Server [thl:0.0.0.0:2112]] INFO  thl.Server THL thread done: store=thl
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,379 [prod - 
pool-2-thread-1] INFO  thl.CommitSeqnoTable Reduced 0 task entries: 
tungsten_prod.trep_commit_seqno
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,381 [prod - 
pool-2-thread-1] INFO  management.OpenReplicatorManager All internal services 
are shut down; replicator ready for recovery
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,381 [prod - 
pool-2-thread-1] INFO  management.OpenReplicatorManager Sent State Change 
Notification ONLINE -> OFFLINE:ERROR
INFO   | jvm 1    | 2014/01/23 11:22:00 | 2014-01-23 11:22:00,423 [prod - 
pool-2-thread-1] WARN  management.OpenReplicatorManager Received irrelevant 
event for current state: state=OFFLINE:ERROR event=OfflineNotification

What version of the product are you using?

Tungsten Replicator 2.1.2 build 44

On what operating system?

Ubuntu / Gentoo

Please provide any additional information below.

Notes:

On a master-slave environment (1 master, 2 slaves) an error occurs on one of 
the slaves when doing consistency checking. The first slave (on which the 
checking works ok) was created with xtrabackup from the master. The second 
slave on which the checking fails was created with mysqldump from the slave.

If I manually compare the tables from mysqldump I see that the data is the 
same, but the order differs.

# diff master.sql slave.sql
136d135
< INSERT INTO `table` VALUES (974,1439,536,1,3,1,1,1,1);
260d258
< INSERT INTO `table` VALUES (975,1439,551,1,4,1,1,1,1);
396a395,396
> INSERT INTO `table` VALUES (974,1439,536,1,3,1,1,1,1);
> INSERT INTO `table` VALUES (975,1439,551,1,4,1,1,1,1);

The table definition:
CREATE TABLE `table` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c1` int(11) NOT NULL,
  `c2` int(11) NOT NULL,
  `c3` int(11) DEFAULT NULL,
  `c4` int(11) DEFAULT NULL,
  `c5` int(11) DEFAULT NULL,
  `c6` int(11) DEFAULT NULL,
  `c7` int(11) DEFAULT NULL,
  `c8` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `c1` (`c1`,`c2`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8

The consistency check was run like:
# ./trepct check db.table

Master runs on MySQL 5.5.25 (binlog_format=row), the slaves run on MySQL 
5.5.25a.

Original issue reported on code.google.com by tomas.mo...@gmail.com on 23 Jan 2014 at 11:57

GoogleCodeExporter commented 9 years ago
How to reproduce:

1. Insert the following data onto the master:

create database base;
CREATE TABLE user1 (id int(11) NOT NULL, name varchar(255) NOT NULL);
INSERT INTO base.user1 (id, name) VALUES (1, 'test1');
INSERT INTO base.user1 (id, name) VALUES (2, 'test2');
INSERT INTO base.user1 (id, name) VALUES (3, 'test3');
INSERT INTO base.user1 (id, name) VALUES (4, 'test4');

CREATE TABLE user2 (id int(11) NOT NULL, name varchar(255) NOT NULL);
INSERT INTO base.user2 (id, name) VALUES (1, 'test1');
INSERT INTO base.user2 (id, name) VALUES (2, 'test2');
INSERT INTO base.user2 (id, name) VALUES (3, 'test3');
INSERT INTO base.user2 (id, name) VALUES (4, 'test4');

2. Create a master-slave replication and copy the data to the slave with 
xtrabackup.

3. Create a mysqldump on the slave and swap the order of the data in table 
user2:
INSERT INTO `user2` VALUES (1,'test1'),(2,'test2'),(3,'test3'),(4,'test4');
->
INSERT INTO `user2` VALUES (1,'test1'),(2,'test2'),(4,'test4'),(3,'test3');

4. Add the second slave to the replication and import the modified dump.

5. On master:
./trepctl check base.user1 - OK
./trepctl check base.user2 - works on the first slave (xtrabackup), fails on 
second slave (mysqldump)

The master / slave1 (xtrabackup):

mysql> select * from user1;
+----+-------+
| id | name  |
+----+-------+
|  1 | test1 |
|  2 | test2 |
|  3 | test3 |
|  4 | test4 |
+----+-------+
4 rows in set (0.00 sec)

mysql> select * from user2;
+----+-------+
| id | name  |
+----+-------+
|  1 | test1 |
|  2 | test2 |
|  3 | test3 |
|  4 | test4 |
+----+-------+
4 rows in set (0.00 sec)

Slave2 (mysqldump):

mysql> select * from user1;
+----+-------+
| id | name  |
+----+-------+
|  1 | test1 |
|  2 | test2 |
|  3 | test3 |
|  4 | test4 |
+----+-------+
4 rows in set (0.00 sec)

mysql> select * from user2;
+----+-------+
| id | name  |
+----+-------+
|  1 | test1 |
|  2 | test2 |
|  4 | test4 |
|  3 | test3 |
+----+-------+
4 rows in set (0.00 sec)

Either way, the following SELECTs give the same result:
mysql> select * from user2 where id=1;
+----+-------+
| id | name  |
+----+-------+
|  1 | test1 |
+----+-------+
1 row in set (0.00 sec)

mysql> select * from user2 where id=2;
+----+-------+
| id | name  |
+----+-------+
|  2 | test2 |
+----+-------+
1 row in set (0.00 sec)

mysql> select * from user2 where id=3;
+----+-------+
| id | name  |
+----+-------+
|  3 | test3 |
+----+-------+
1 row in set (0.00 sec)

mysql> select * from user2 where id=4;
+----+-------+
| id | name  |
+----+-------+
|  4 | test4 |
+----+-------+
1 row in set (0.00 sec)

Original comment by tomas.mo...@gmail.com on 23 Jan 2014 at 12:45

GoogleCodeExporter commented 9 years ago
Hi Tomas,

try adding a primary key to the id column in user1 and user2 tables on both 
sides and repeat the test - it should work. If there's no PK, there's no 
consistent way of ordering rows between different DBMS instances, hence 
consistency check failure.

Cheers,
Linas

Original comment by linas.vi...@continuent.com on 27 Jan 2014 at 12:16

GoogleCodeExporter commented 9 years ago
Hello,
after modifying the table creation to be more specific:
CREATE TABLE base.user1 (id int(11) NOT NULL, name varchar(255) NOT NULL, 
PRIMARY KEY (id)) ENGINE=MyISAM
CREATE TABLE base.user2 (id int(11) NOT NULL, name varchar(255) NOT NULL, 
PRIMARY KEY (id)) ENGINE=MyISAM

the same error appears:
Consistency check failed on table 'base.user2' id: 2, offset: -1, limit: -1, 
method: 'md5' failed

As pointed out in the first comment, the production table on which this 
happened already had a primary key on `id`.

- mysqldump on master/slave (xtrabackup):

--
-- Table structure for table `user1`
--

DROP TABLE IF EXISTS `user1`;
/*!40101 SET @saved_cs_client     = @@character_set_client */;
/*!40101 SET character_set_client = utf8 */;
CREATE TABLE `user1` (
  `id` int(11) NOT NULL,
  `name` varchar(255) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8;
/*!40101 SET character_set_client = @saved_cs_client */;

--
-- Dumping data for table `user1`
--

LOCK TABLES `user1` WRITE;
/*!40000 ALTER TABLE `user1` DISABLE KEYS */;
INSERT INTO `user1` VALUES (1,'test1'),(2,'test2'),(3,'test3'),(4,'test4');
/*!40000 ALTER TABLE `user1` ENABLE KEYS */;
UNLOCK TABLES;

--
-- Table structure for table `user2`
--

DROP TABLE IF EXISTS `user2`;
/*!40101 SET @saved_cs_client     = @@character_set_client */;
/*!40101 SET character_set_client = utf8 */;
CREATE TABLE `user2` (
  `id` int(11) NOT NULL,
  `name` varchar(255) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8;
/*!40101 SET character_set_client = @saved_cs_client */;

--
-- Dumping data for table `user2`
--

LOCK TABLES `user2` WRITE;
/*!40000 ALTER TABLE `user2` DISABLE KEYS */;
INSERT INTO `user2` VALUES (1,'test1'),(2,'test2'),(3,'test3'),(4,'test4');
/*!40000 ALTER TABLE `user2` ENABLE KEYS */;
UNLOCK TABLES;

- mysqldump on slave with differently ordered data:

--
-- Table structure for table `user1`
--

DROP TABLE IF EXISTS `user1`;
/*!40101 SET @saved_cs_client     = @@character_set_client */;
/*!40101 SET character_set_client = utf8 */;
CREATE TABLE `user1` (
  `id` int(11) NOT NULL,
  `name` varchar(255) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8;
/*!40101 SET character_set_client = @saved_cs_client */;

--
-- Dumping data for table `user1`
--

LOCK TABLES `user1` WRITE;
/*!40000 ALTER TABLE `user1` DISABLE KEYS */;
INSERT INTO `user1` VALUES (1,'test1'),(2,'test2'),(3,'test3'),(4,'test4');
/*!40000 ALTER TABLE `user1` ENABLE KEYS */;
UNLOCK TABLES;

--
-- Table structure for table `user2`
--

DROP TABLE IF EXISTS `user2`;
/*!40101 SET @saved_cs_client     = @@character_set_client */;
/*!40101 SET character_set_client = utf8 */;
CREATE TABLE `user2` (
  `id` int(11) NOT NULL,
  `name` varchar(255) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8;
/*!40101 SET character_set_client = @saved_cs_client */;

--
-- Dumping data for table `user2`
--

LOCK TABLES `user2` WRITE;
/*!40000 ALTER TABLE `user2` DISABLE KEYS */;
INSERT INTO `user2` VALUES (1,'test1'),(2,'test2'),(4,'test4'),(3,'test3');
/*!40000 ALTER TABLE `user2` ENABLE KEYS */;
UNLOCK TABLES;

Original comment by tomas.mo...@gmail.com on 31 Jan 2014 at 7:52