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

[PATCH] Slave SQL: stopping on non-last RBR event with annotations results in SEGV (signal 11)

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Fixed
    • 10.0.17
    • 10.0.18
    • Replication
    • x86_64, RHEL6, 5.5.39 master to 10.0.17 slave on same machine

    Description

      while replicating from a 5.5.39 master to a 10.0.17 slave the following repeatable segfault resulted.

      150327 22:39:10 [Note] Master '5.5': Slave SQL thread initialized, starting replication in log 'tulwaurt005-mysql-bin.000687' at position 649581827, relay log './tulwaurt005-relay-bin-5@002e5.000004' position: 649582126
      150327 22:39:10 [ERROR] Master '5.5': Slave SQL: Could not execute Delete_rows_v1 event on table X_20150210.feed_lookup; Can't find record in 'feed_lookup', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log tulwaurt005-mysql-bin.000687, end_log_pos 649583202, Internal MariaDB error code: 1032
      150327 22:39:10 [Warning] Master '5.5': Slave: Can't find record in 'feed_lookup' Error_code: 1032
      50327 22:39:10 [ERROR] Master '5.5': Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'tulwaurt005-mysql-bin.000687' position 649581827
      150327 22:39:10 [ERROR] mysqld got signal 11 ;
      This could be because you hit a bug. It is also possible that this binary
      or one of the libraries it was linked against is corrupt, improperly built,
      or misconfigured. This error can also be caused by malfunctioning hardware.
       
      To report this bug, see http://kb.askmonty.org/en/reporting-bugs
       
      We will try our best to scrape up some info that will hopefully help
      diagnose the problem, but since we have already crashed,
      something is definitely wrong and this may fail.
       
      Server version: 10.0.17-MariaDB-log
      key_buffer_size=209715200
      read_buffer_size=262144
      max_used_connections=1
      max_threads=3202
      thread_count=1
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 7648478 K  bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.
       
      Thread pointer: 0x0x7fc97002d008
      Attempting backtrace. You can use the following information to find out
      where mysqld died. If you see no messages after this, something went
      terribly wrong...
      stack_bottom = 0x7fc9523ef870 thread_stack 0x48000
      /opt/mariadb-10/sbin/mysqld(my_print_stacktrace+0x2b)[0xb743db]
      /opt/mariadb-10/sbin/mysqld(handle_fatal_signal+0x398)[0x726a38]
      /lib64/libpthread.so.0[0x3353a0f500]
      150327 22:39:10 [Note] Master '5.5': Slave I/O thread: connected to master 'repl@localhost:3306',replication started in log 'tulwaurt005-mysql-bin.000702' at position 957219213
      /opt/mariadb-10/sbin/mysqld(_ZN14rpl_group_infoD2Ev+0x18)[0x68e148]
      /opt/mariadb-10/sbin/mysqld(handle_slave_sql+0x21c)[0x56576c]
      /lib64/libpthread.so.0[0x3353a07851]
      /lib64/libc.so.6(clone+0x6d)[0x33536e890d]
       
      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0x0): is an invalid pointer
      Connection ID (thread ID): 25

      mysqlbinlog --start-position 649582126  tulwaurt005-relay-bin-5@002e5.000004 | more
      # at 649582126
      #150324  4:45:21 server id 76  end_log_pos 649581906    Query   thread_id=10229406      exec_time=3     error_code=0
      SET TIMESTAMP=1427138121/*!*/;
      SET @@session.pseudo_thread_id=10229406/*!*/;
      SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
      SET @@session.sql_mode=0/*!*/;
      SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
      /*!\C utf8 *//*!*/;
      SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
      SET @@session.lc_time_names=0/*!*/;
      SET @@session.collation_database=DEFAULT/*!*/;
      BEGIN
      /*!*/;
      # at 649582205
      # at 649582454
      # at 649582526
      # at 649583501
      # at 649584476
      # at 649585451
      # at 649586426
      # at 649587401
      # at 649588376
      # at 649589351
      # at 649590326
      # at 649591301
      # at 649592276
      # at 649593251
      # at 649594226
      # at 649595201
      # at 649596176
      # at 649597151
      # at 649598126
      # at 649599101
      # at 649600076
      # at 649601051
      # at 649602026
      # at 649603001
      # at 649603976
      # at 649604951
      # at 649605926
      # at 649606901
      # at 649607876
      # at 649608851
      # at 649609826
      # at 649610801
      # at 649611776
      # at 649612751
      # at 649613726
      # at 649614701
      # at 649615676
      # at 649616651
      # at 649617626
      # at 649618601
      # at 649619576
      # at 649620551
      # at 649621526
      # at 649622501
      # at 649623476
      # at 649624451
      # at 649625426
      # at 649626401
      # at 649627376
      # at 649628351
      # at 649629326
      # at 649630301
      # at 649631276
      # at 649632251
      # at 649633226
      # at 649634201
      # at 649635176
      # at 649636151
      # at 649637126
      # at 649638101
      # at 649639076
      # at 649640051
      # at 649641026
      # at 649642001
      # at 649642976
      # at 649643951
      # at 649644926
      # at 649645901
      # at 649646876
      # at 649647851
      # at 649648826
      # at 649649801
      # at 649650776
      # at 649651751
      # at 649652726
      #150324  4:45:21 server id 76  end_log_pos 649582155    Annotate_rows:
      #Q> /*wp_r4 (MASTER)*/DELETE feed_lookup
      #Q>                     FROM feed_lookup
      #Q>                             LEFT JOIN market_prices ON (feed_lookup.id=market_prices.market_prices_id)
      #Q>                     WHERE feed_lookup.entity_type="market_price"
      #Q>                             AND market_prices.market_prices_id IS 
      #150324  4:45:21 server id 76  end_log_pos 649582227    Table_map: `X_20150210`.`feed_lookup` mapped to number 418
      #150324  4:45:21 server id 76  end_log_pos 649583202    Delete_rows: table id 418
      #150324  4:45:21 server id 76  end_log_pos 649584177    Delete_rows: table id 418
      #150324  4:45:21 server id 76  end_log_pos 649585152    Delete_rows: table id 418
      ..
      #150324  4:45:21 server id 76  end_log_pos 649653144    Delete_rows: table id 418 flags: STMT_END_F
      ### DELETE FROM `X_20150210`.`feed_lookup`
      ### WHERE
      ###   @1=2065190
      ###   @2=245216596
      ###   @3='FcOKws8fYwPEPs55vjI-uWAyyRA'
      ###   @4=-117 (4294967179)
      ###   @5='market_price'
      ###   @6='YYbb8jzsfDm9MU25_bdbSQmbYLA'
      ### DELETE FROM `X_20150210`.`feed_lookup`
      ### WHERE
      ###   @1=2065191
      ###   @2=245216597
      ###   @3='g2XXXXXXX'
      ###   @4=-117 (4294967179)
      ###   @5='XXXXXXX'
      ###   @6='jeXXXXXXX0'
      ### DELETE FROM `X_20150210`.`feed_lookup`
      ### WHERE
      ###   @1=2065192
      ###   @2=245216598
      ###   @3='X3XXXXXXXXXX'
      ###   @4=-117 (4294967179)
      ###   @5='XXXXXXXX'
      ###   @6='DCXXXXXXX'
       

      As the error quite rightly points out the roes are missing on the slave

       select * from feed_lookup where lookup_id in ( 2065191, 2065192);
      Empty set (0.02 sec)

      Raw binlog in private uploads

      Attachments

        1. slave-status.txt
          2 kB
          Daniel Black
        2. mysqld-10.log
          19 kB
          Daniel Black

        Issue Links

          Activity

            danblack Daniel Black added a comment -

            changed title because this is the general case when stopping a slave with binlog annotations and the rbr event isn't the last one.

            To be clear this only affects 10.0, doesn't affect 5.5

            danblack Daniel Black added a comment - changed title because this is the general case when stopping a slave with binlog annotations and the rbr event isn't the last one. To be clear this only affects 10.0, doesn't affect 5.5
            danblack Daniel Black added a comment - corrected test case. Fixed regression. https://github.com/MariaDB/server/pull/49 test run: https://travis-ci.org/openquery/mariadb-server/jobs/59977445

            Pushed into 10.0.18.

            Thanks, Daniel for the bug analysis and test case!

            I fixed the bug in a different way. I think the clearing of serial_rgi->thd
            just before deleting serial_rgi just does not make any sense. It was
            introduced in this commit, without any justification that I can see:

              commit 2e100cc5a493b6a0f6f907e0483a734c7fee2087
              Author: Michael Widenius <monty@askmonty.org>
              Date:   Mon Oct 14 00:24:05 2013 +0300

            So I fixed by simply reverting that part of that change (one line).

            knielsen Kristian Nielsen added a comment - Pushed into 10.0.18. Thanks, Daniel for the bug analysis and test case! I fixed the bug in a different way. I think the clearing of serial_rgi->thd just before deleting serial_rgi just does not make any sense. It was introduced in this commit, without any justification that I can see: commit 2e100cc5a493b6a0f6f907e0483a734c7fee2087 Author: Michael Widenius <monty@askmonty.org> Date: Mon Oct 14 00:24:05 2013 +0300 So I fixed by simply reverting that part of that change (one line).

            Hm, I now noticed you actually suggested this way to fix in an earlier comment.

            I still think this is the right fix (just removing the clear of serial_rgi->thd). But do let me know if you think there is a reason that a different fix is needed.

            knielsen Kristian Nielsen added a comment - Hm, I now noticed you actually suggested this way to fix in an earlier comment. I still think this is the right fix (just removing the clear of serial_rgi->thd). But do let me know if you think there is a reason that a different fix is needed.
            danblack Daniel Black added a comment -

            While I agree that what you've done is the simplest fix.

            I added the condition here in free_annotate_events because I wasn't 100% sure that all the calls to free_annotate event in rpl_parallel.cc occurred when the thread was valid. Are you? Is one extra non-zero check in a thread termination to prevent a future segfault worthwhile ?

            https://github.com/MariaDB/server/blob/71c5275fbe0a62ea1950695c158cc7256fc7195e/sql/rpl_rli.h#L746

            I assumed the reason this bug crept in in the first place is because the ambiguity about whether this was a structure that just stores fields or actually exhibits some abstraction of data responsibility for its on management. To move it more into the latter category is the reason for the other few changes https://github.com/MariaDB/server/pull/49/files

            danblack Daniel Black added a comment - While I agree that what you've done is the simplest fix. I added the condition here in free_annotate_events because I wasn't 100% sure that all the calls to free_annotate event in rpl_parallel.cc occurred when the thread was valid. Are you? Is one extra non-zero check in a thread termination to prevent a future segfault worthwhile ? https://github.com/MariaDB/server/blob/71c5275fbe0a62ea1950695c158cc7256fc7195e/sql/rpl_rli.h#L746 I assumed the reason this bug crept in in the first place is because the ambiguity about whether this was a structure that just stores fields or actually exhibits some abstraction of data responsibility for its on management. To move it more into the latter category is the reason for the other few changes https://github.com/MariaDB/server/pull/49/files

            People

              knielsen Kristian Nielsen
              danblack Daniel Black
              Votes:
              0 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.