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

Row-based event is not applied when table map id is greater 32 bit int

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Fixed
    • 10.1.26
    • 10.4.2, 10.1.38, 10.0.38, 10.2.22, 10.3.13
    • Replication

    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?

      Attachments

        1. db03.txt
          520 kB
        2. db02.my.cnf
          4 kB
        3. db03.my.cnf
          2 kB

        Issue Links

          Activity

            mapa Maik Pätzold added a comment - - edited

            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?

            mapa Maik Pätzold added a comment - - edited 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?
            Elkin Andrei Elkin added a comment -

            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

            Elkin Andrei Elkin added a comment - 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
            mapa Maik Pätzold added a comment -

            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...

            mapa Maik Pätzold added a comment - 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...
            mapa Maik Pätzold added a comment - - edited

            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)

            mapa Maik Pätzold added a comment - - edited 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)
            mapa Maik Pätzold added a comment -

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

            mapa Maik Pätzold added a comment - do you have any idea whats the difference between MariaDB 10.1 and MySQL 5.6 regarding replication and could cause such a behaviour?
            Elkin Andrei Elkin added a comment -

            > 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.

            Elkin Andrei Elkin added a comment - > 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.
            Elkin Andrei Elkin added a comment -

            > 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.

            Elkin Andrei Elkin added a comment - > 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.
            mapa Maik Pätzold added a comment -

            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...)

            mapa Maik Pätzold added a comment - 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...)
            Elkin Andrei Elkin added a comment -

            >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.

            Elkin Andrei Elkin added a comment - >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.
            ruochen wy added a comment -
            ruochen wy added a comment - table_id overflow? FYI: https://jira.mariadb.org/browse/MDEV-18175
            mapa Maik Pätzold added a comment - - edited

            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?

            mapa Maik Pätzold added a comment - - edited 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?
            ruochen wy added a comment - - edited

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

            ruochen wy added a comment - - edited Maik yes,you are right,it's 2^32 - 1.
            mapa Maik Pätzold added a comment -

            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 ...

            mapa Maik Pätzold added a comment - 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 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: at 71616759 #190108 8:03:42 server id 12 end_log_pos 71616827 Table_map: `supremeshops`.`supr_send_cloud` mapped to number 4296337457 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 ...
            mapa Maik Pätzold added a comment -

            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?

            mapa Maik Pätzold added a comment - 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?
            Elkin Andrei Elkin added a comment -

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

            Elkin Andrei Elkin added a comment - mapa Your latest data points to MDEV-18175 , indeed. I'll try to come up with a patch shortly.
            mapa Maik Pätzold added a comment -

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

            mapa Maik Pätzold added a comment - Elkin i've changed the uint table_id in sql/table.h to ulong table_id and reattached the slave like described above -> Works
            mapa Maik Pätzold added a comment -

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

            mapa Maik Pätzold added a comment - Elkin do you known if the table_id maybe increasing faster because of we have ~800k tables in one database?
            Elkin Andrei Elkin added a comment -

            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.

            Elkin Andrei Elkin added a comment - 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.
            mapa Maik Pätzold added a comment -

            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?

            mapa Maik Pätzold added a comment - 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?
            Elkin Andrei Elkin added a comment - - edited

            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?

            Elkin Andrei Elkin added a comment - - edited 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?
            Elkin Andrei Elkin added a comment -

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

            Elkin Andrei Elkin added a comment - mapa , sorry, we seem to have been working on the same thing without coordination. I appreciate your help!
            mapa Maik Pätzold added a comment -

            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?

            mapa Maik Pätzold added a comment - 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?
            Elkin Andrei Elkin added a comment -

            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.

            Elkin Andrei Elkin added a comment - 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.
            Elkin Andrei Elkin added a comment -

            Patch cce2b45c8f5b32 was actually pushed back in January.

            Elkin Andrei Elkin added a comment - Patch cce2b45c8f5b32 was actually pushed back in January.

            People

              Elkin Andrei Elkin
              mapa Maik Pätzold
              Votes:
              1 Vote for this issue
              Watchers:
              4 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.