[MDEV-17803] Row-based event is not applied when table map id is greater 32 bit int Created: 2018-11-22  Updated: 2019-05-29  Resolved: 2019-05-29

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1.26
Fix Version/s: 10.4.2, 10.1.38, 10.0.38, 10.2.22, 10.3.13

Type: Bug Priority: Major
Reporter: Maik Pätzold Assignee: Andrei Elkin
Resolution: Fixed Votes: 1
Labels: replication
Environment:

2x XEN PV Guest with Debian 9 with a Master/Slave Replication Setup

DB01 Guest Hosted on:
XEN 4.8.4
2x AMD Opteron 6136 (total of 16 Cores)
2x10G Network (LACP)
SSD (4x Enterprise SSD in RAID10 dedicated to this Guest) SAN with 8x10G Network

DB02 Guest Hosted on:
XEN 4.8.3
2x AMD Opteron 6370P (total of 32 Cores)
2x10G Network (LACP)
SSD (4x Enterprise SSD in RAID10 dedicated to this Guest) SAN with 4x10G Network

Each Guest with:
8 vCPU's
32G of RAM
300GB Disk (entire mounted as /)
8GB Swap (mounted from file in /)
MariaDB 10.1.26 from Debian Repo
~12 Databases with ~150GB disk space used
1 Database with ~700k tables

Attachments: File db02.my.cnf     File db03.my.cnf     Text File db03.txt    
Issue Links:
Duplicate
is duplicated by MDEV-15660 Problematic BINLOG events from master Closed
is duplicated by MDEV-18175 table id overflow causes replication ... Closed
Relates
relates to MDEV-15660 Problematic BINLOG events from master Closed

 Description   

Because of privacy reasons I can’t share as much data i’d like to, but hopefully you can help anyway.
To have the whole Story… what happened:

In February 2018 we migrated a customer from a MySQL 5.5 Master/Master to a MariaDB 10.1 Master/Master Setup.
Because the Customer have one Big Database with around 700k Tables and a Dump took several days, we have done the migration by the following Steps:

1. Stop Replication on one of the MySQL Master, create a Dump via mysqldump and note replication position
2. Setup MariaDB Server named DB01 and import Dump from 1.
3. Configure DB01 as a Slave of the opposite MySQL Server from 1. With the positions from 1.
4. Let DB01 Catch up and run as slave
5. Stop All Maschines, except DB01.
6. Note master position + file from and stop DB01.
6. Create a snapshot of DB01
7. Configure the snapshot as new server DB02 (change name/network/server id/increment offset/…)
8. Start DB01 and DB02.
9. Configure DB02 as Slave of DB01 With data from 6.
10. Configure DB01 As Slave from DB02 (because no one works on it by note master pos/file from DB02)
11. Configure keepalived so we have a cluster ip
12. Migrate all applications the the ClusterIP from 11.

From that Point we had a MariaDB Master/Master „Cluster“ Setup working….
And this Setup worked without any changes for round about 8 Months, until 23th of October.

At 2018-10-23 10:55:59 Replication stopped on DB01 because of a foreign key constraint violation. At and before this point in time the ClusterIP was Pointing to DB02, so DB02 could be treated as MASTER and DB01 as SLAVE. For a better understanding we could assume the following tables:

Order
Address
Order_item

All with auto_increment id’s as primary key, and the following foreign keys (with null allowed and as default):

Order.address_id -> Address.id
Order.delivery_address_id -> Address.id
Order_item.order_id -> Order.id

The Constraint violation happened for the Order_item.order_id, So the corresponding Order does not exist. We had a look on DB02 -> as expected the Order and all related exists on the „Master“ and as well expected because of the issue on DB01 none of it exists. So we started inspecting the corresponding binlog events on DB02:

mysql-bin.001407 68765085 Table_map             12     68765287 table_id: 4297936365 (Order)
mysql-bin.001407 68765287 Table_map             12     68765489 table_id: 4297936365 (Order) 
mysql-bin.001407 68765489 Write_rows_v1         12     68765660 table_id: 4297936365 flags: STMT_END_F
mysql-bin.001407 68765660 Xid                   12     68765687 COMMIT /* xid=1845363106 */
mysql-bin.001407 68765687 Gtid                  12     68765725 BEGIN GTID 0-12-569302375
mysql-bin.001407 68765725 Intvar                12     68765753 INSERT_ID=501448
mysql-bin.001407 68765753 Query                 12     68766164 INSERT INTO Address ...
mysql-bin.001407 68766164 Query                 12     68766977 UPDATE `Order` SET ..., `address_id`='501448', `delivery_address_id`='501448' WHERE Order.id='471850'
mysql-bin.001407 68766977 Intvar                12     68767005 INSERT_ID=1329576        
mysql-bin.001407 68767005 Query 12 68767678 INSERT INTO Order_item ...

The Replication on DB01 stopped with exec master position at 68765489 and complaining the insert at 68767005...
On DB01 the binlog events showed (this is a copy after we tried to recover the slave by reset slave and reattach):

mysqld-relay-bin.000002 537 Gtid 12 68765085 BEGIN GTID 0-12-569302374
mysqld-relay-bin.000002 249 Rotate 12 0 mysql-bin.001407;pos=68765047
mysqld-relay-bin.000002 292 Format_desc 12 0 Server ver: 10.1.26-MariaDB-0+deb9u1, Binlog ver: 4
mysqld-relay-bin.000002 537 Gtid 12 68765085 BEGIN GTID 0-12-569302374
mysqld-relay-bin.000002 575 Table_map 12 68765287 table_id: 4297936365 (Order)
mysqld-relay-bin.000002 777 Table_map 12 68765489 table_id: 4297936365 (Order)
mysqld-relay-bin.000002 979 Write_rows_v1 12 68765660 table_id: 4297936365 flags: STMT_END_F
mysqld-relay-bin.000002 1150 Xid 12 68765687 COMMIT /* xid=1845363106 */
mysqld-relay-bin.000002 1177 Gtid 12 68765725 BEGIN GTID 0-12-569302375
mysqld-relay-bin.000002 1215 Intvar 12 68765753 INSERT_ID=501448
mysqld-relay-bin.000002 1243 Query 12 68766164 INSERT INTO `Address` ...
mysqld-relay-bin.000002 1654 Query 12 68766977 UPDATE `Order` SET ..., `address_id`='501448', `delivery_address_id`='501448' WHERE Order.id='471850'
mysqld-relay-bin.000002 2467 Intvar 12 68767005 INSERT_ID=1329576

somehow i did not copied until the Order_item insert, but it was right behind 2467 and the failed one.
Things to mention:

  • the missing Order is replicated row based
  • while inspecting more of the logs we noticed that some row-based events (and this applies to the missing Order) has no Format_desc right before the event (as others have)

So we tried to insert the missing Order manually and continue replication... but this only worked until the next order/order_item insert. So we had a persistent problem...
Because we couldn't fix the replication we decided to rebuild the "cluster" by the following steps:

1. Stop DB02, make make a Snapshot and restart DB02
2. Overwrite DB01 with the Snapshot from 1. And configure network/name/server_id and so on...
3. Create a new DB03 within the Snapshot like in 2.
4. Start DB01 with network disabled
5. Note master file/position from DB01, enabled network and reattach to DB02 as a slave with this infos
6. Attach DB03 as a second Slave to DB02 with the infos from 5.

From this Point we had a Master and 2 Slaves. The Slaves catched up and all was working...
For around 3 weeks until 14th of November.

At 2018-11-14 17:42:33 Replication stopped on both, DB01 and DB03 Slaves with the exact same position and similar Statement as the first Problem (Missing Order for INSERT INTO Order_item)

So from our understanding the entire Problem is somehow related to the row-based replication event which is somehow skipped or silent dropped or something like that?

Do you have any ideas what could cause a problem like this?

 Comments   
Comment by Maik Pätzold [ 2018-12-18 ]

Update: after the last replication outage (2018-11-14) we added more slaves like described above. So we had the following machines:

  • DB02 as Master with MariaDB 10.1
  • DB01 as SLAVE with MariaDB 10.1
  • DB03 as SLAVE with MariaDB 10.3
  • DB04 as SLAVE with downgrade to MySQL 5.6

Additionaly we changed the binlog format to ROW instead of MIXED

at 2018-12-11 we had another outage and this time it's even worse... :

  • SHOW SLAVE STATUS on all machines still shows zero replication lag... and all seems OK !
  • But for DB01 + DB03 (both mariadb) no more changes happen (added orders on DB02 are not added on DB01 + DB03) -> but Exec_Master_Log_Pos is increasing
  • DB04 (MySQL) seems to run as expected (no replication lag and changes on DB02 get applied)
  • It seems there is some periodically now in the outages: the second one happend after 18, the third after 19 days...

any ideas?

Comment by Andrei Elkin [ 2018-12-20 ]

Thanks for reporting, Maik!

It's difficult to grasp your setup. If I got it right (as you say 'master-master' and 'cluster'), two servers replicated crisscross DB01 <-> DB02 ?
I understood that you suspect that an INSERT (Write_rows_log_event) was not applied by that slave.

If it's really crisscross setup, I naturally wonder how it's guaranteed that local data modification does not conflict with replication.
Assuming it's all proved to be safe for you and then indeed it's replication to blame, you need continue with your method to identify
a missed-to-apply replication event in the master binlog, also check the entire transaction that it belongs to whether it was skipped entirely. Please tell us when such event/transaction will be firmly identified, so we could
check that closer.

Also it would be helpful to provide

show global status,  show global variables, my.cnf of master and slaves
 
SHOW ALL SLAVES STATUS on the slaves.

Good luck,

Andrei

Comment by Maik Pätzold [ 2018-12-20 ]

Hey Andrei,

almost right...
it was a master/master early 2018 and we used the following methods to prevent conflicts:
1. Use Keepalive to provide a ClusterIP (each server in BACKUP Mode so the ip is not "flapping"
2. Allow access to the Database only via the ClusterIP
3. Configure each server with a different another auto_increment_offset (1 and 2) and set auto_increment_increment to 2.

But after the first Replication Problem we moved to a Master/Slave (by get a snapshot of the last master (DB02) and configure it as a slave...) So since 23th October we no longer have a "crisscross" Setup...

Comment by Maik Pätzold [ 2018-12-20 ]

i've attached db03.txt which contains the requested outputs of one of the mariadb slave (DB03) which is no longer applying changes. As well as db02.my.conf (MASTER my.cnf) and db03.my.cnf (SLAVE my.cnf)

Comment by Maik Pätzold [ 2018-12-20 ]

do you have any idea whats the difference between MariaDB 10.1 and MySQL 5.6 regarding replication and could cause such a behaviour?

Comment by Andrei Elkin [ 2018-12-20 ]

> 3. Configure each server with a different another auto_increment_offset (1 and 2) and set auto_increment_increment to 2.

Sure in such case auto-increment INSERT:s are okay, but there are UPDATE:s according to your snippet.
I am not convinced yet in conflict-free master-master of your setup.

However as you clarified the missed record error has occurred now in the master-slave.
Let me understand the very error now.

A piece of your comments start with

> The Replication on DB01 stopped with exec master position at 68765489

to say the error must have happened at applying

mysql-bin.001407 	68765489 	Write_rows_v1 	        12 	    68765660 	table_id: 4297936365 flags: STMT_END_F

but I could not get the meaning of the 2nd part of the comments:

>and complaining the insert at 68767005

which refer to a following event.

I need your explanation.

I could imagine that the error actually happened at the 2nd INSERT of 68767005, and you found at your analysis it's the 1st 68765489 that did not make its job. But I can't read it this way.

Comment by Andrei Elkin [ 2018-12-20 ]

> whats the difference between MariaDB 10.1 and MySQL 5.6 regarding replication

Generally we have few differences, but I don't see how any of them can relate to your case.

Comment by Maik Pätzold [ 2018-12-20 ]

i think you read it right...
As you say, the second comment (insert at 68767005) stopped the replication with an foreign key constraint violation, which happend because the first one (68765489) was not applied.. (and more worse it raised no error! so some kind of silent ignored...)

Comment by Andrei Elkin [ 2018-12-20 ]

>the second comment (insert at 68767005) stopped the replication with an foreign key constraint violation

That means BEGIN GTID 0-12-569302375 transaction (gtid group) which this insert belongs to.
And the suspected insert belongs to a preceding one.
And this looks quite easy to analyze then.

If you have a slave "frozen" after this error I could try to help you to unroll what might have happened.
Otherwise we seem have to wait for perhaps another period that you spotted.

Comment by wy [ 2019-01-10 ]

table_id overflow?

FYI：https://jira.mariadb.org/browse/MDEV-18175

Comment by Maik Pätzold [ 2019-01-10 ]

2019-01-08 we hit another replication outage...
The table_id idea is interesting, it seems that every time we hit this Problem, table_id is greater than 2^32 - 1 (4297936365 last, 4296337452 current) (https://jira.mariadb.org/browse/MDEV-18175 says something about > 17179869184 which is wired to me because either uint is 32 or 64 bits which both would'nt match that number?). Is the computation of the table_id somehow related to the number of tables? [Andrei Elkin] we currently have such a frozen slave, is some kind of remote session possible for you?

Comment by wy [ 2019-01-10 ]

Maik
yes，you are right，it's 2^32 - 1.

Comment by Maik Pätzold [ 2019-01-10 ]

ok, for me it sounds really close to our problem...

Last Events wich are inserted at slave:

#190108 7:51:30 server id 12 end_log_pos 62304235 Table_map: `supremeshops`.`supr_send_cloud` mapped to number 4294743012

  1. at 62304235
    #190108 7:51:30 server id 12 end_log_pos 62304406 Write_rows: table id 4289245655 flags: STMT_END_F

And the Problem begins with:

  1. at 71616759
    #190108 8:03:42 server id 12 end_log_pos 71616827 Table_map: `supremeshops`.`supr_send_cloud` mapped to number 4296337457
  2. at 71616827
    #190108 8:03:42 server id 12 end_log_pos 71616998 Write_rows: table id 4296337452 flags: STMT_END_F

From that Point we have a table_id > 2^32 - 1 ...

Comment by Maik Pätzold [ 2019-01-10 ]

so if i got it right the Problem is slave related and we could prove that this is our Problem bei starting a fixed slave and attach it to the binlog position with the silent dropped insert. The fixed slave now should replicate again, right?

Comment by Andrei Elkin [ 2019-01-10 ]

mapa Your latest data points to MDEV-18175, indeed. I'll try to come up with a patch shortly.

Comment by Maik Pätzold [ 2019-01-10 ]

Elkin i've changed the uint table_id in sql/table.h to ulong table_id and reattached the slave like described above -> Works

Comment by Maik Pätzold [ 2019-01-10 ]

Elkin do you known if the table_id maybe increasing faster because of we have ~800k tables in one database?

Comment by Andrei Elkin [ 2019-01-10 ]

mapa Right, the reason is the short type of TABLE_LIST::table_id. Well done!

table id in TABLE_SHARE::table_map_id changes by each ALTER. And it's of 8 bytes.

Comment by Maik Pätzold [ 2019-01-10 ]

just to be sure.... Is there something more to change? https://github.com/mysql/mysql-server/commit/c9c7bda021b8d4d7aa997f24e301df5b76dfe215

maybe it's a good idea to use a typedef for table_id to have the same type across the entire code, like mysql does it?

Comment by Andrei Elkin [ 2019-01-10 ]

sachin.setiya.007, there has been activity on two tickets - MDEV-17803, MDEV-18175 with couple of people involved. Since the older one had had some history I could not resist from fixing it. The 2nd is a dup. Could you please check out the patch?

Comment by Andrei Elkin [ 2019-01-10 ]

mapa, sorry, we seem to have been working on the same thing without coordination. I appreciate your help!

Comment by Maik Pätzold [ 2019-01-11 ]

Elkin that's just me quick and dirty change i've done to test/prove that this is the reason of our Problem... so it is i thought i should contribute it because i did not excpected that you find time to start on that topic that fast . Cause i only have that short qnd fix please push/PR your changes, i close my PR?

Comment by Andrei Elkin [ 2019-01-11 ]

mapa We always love to have contributions. ruochen and yourself did a great job, thank you both!
I could not defer (and said that yesterday with 'shortly') with this case fast having seen its history and active interest of few people.

Yes, please close PR, my "internal" patch is being reviewed.

Comment by Andrei Elkin [ 2019-05-29 ]

Patch cce2b45c8f5b32 was actually pushed back in January.

Generated at Thu Feb 08 08:39:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.