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

SIGSEGV in __memmove_avx_unaligned_erms from _my_b_write and Assertion `Count >= rest_length' failed in _my_b_write

    XMLWordPrintable

Details

    Description

      Possibilty related to MDEV-17977 and/or MDEV-24625. Lightly sporadic. No issues observed on UBSAN or ASAN.

      # mysqld options required for replay: --log-bin
      CREATE EVENT e ON SCHEDULE AT CURRENT_TIMESTAMP DO ALTER TABLE tp EXCHANGE PARTITION p WITH TABLE t;
      DUMMY_ERROR;
      SET GLOBAL event_scheduler=ON;
      RESET MASTER TO 5000000000;
      SELECT SLEEP(2);  # Not required; shows server crashed
      

      Leads to:

      11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Optimized)

      Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
      Program terminated with signal SIGSEGV, Segmentation fault.
      #0  __memmove_avx_unaligned_erms ()
          at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:575
      [Current thread is 1 (Thread 0x149a3d71c640 (LWP 1776352))]
      (gdb) bt
      #0  __memmove_avx_unaligned_erms () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:575
      #1  0x000055f2f4bb2f65 in memcpy (__len=18446649571684363816, __src=0x149a3d71a8f0, __dest=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string_fortified.h:29
      #2  _my_b_write (info=0x55f2f557dce0 <mysql_bin_log+800>, Buffer=0x149a3d71a8f0 "\220\367\301c\242d", Count=19) at /test/11.0_opt/mysys/mf_iocache.c:554
      #3  0x000055f2f484abda in Log_event_writer::write_internal (this=0x149a3d71aa20, pos=<optimized out>, len=19) at /test/11.0_opt/sql/log_event_server.cc:808
      #4  0x000055f2f485275a in Log_event::write_header (this=this@entry=0x149a3d71aae0, event_data_length=event_data_length@entry=19) at /test/11.0_opt/sql/log_event_server.cc:995
      #5  0x000055f2f4853487 in Gtid_log_event::write (this=0x149a3d71aae0) at /test/11.0_opt/sql/log_event_server.cc:3737
      #6  0x000055f2f482cc8e in Log_event_writer::write (ev=0x149a3d71aae0, this=0x149a3d71aa20) at /test/11.0_opt/sql/log_event.h:5831
      #7  MYSQL_BIN_LOG::write_event (this=this@entry=0x55f2f557d9c0 <mysql_bin_log>, ev=ev@entry=0x149a3d71aae0, cache_data=cache_data@entry=0x0, file=file@entry=0x55f2f557dce0 <mysql_bin_log+800>) at /test/11.0_opt/sql/log.cc:5613
      #8  0x000055f2f482e102 in MYSQL_BIN_LOG::write_event (ev=0x149a3d71aae0, this=0x55f2f557d9c0 <mysql_bin_log>) at /test/11.0_opt/sql/log.h:833
      #9  MYSQL_BIN_LOG::write_gtid_event (this=0x55f2f557d9c0 <mysql_bin_log>, thd=0x1499f8000f38, standalone=<optimized out>, is_transactional=<optimized out>, commit_id=0, has_xid=<optimized out>, is_ro_1pc=false) at /test/11.0_opt/sql/log.cc:6501
      #10 0x000055f2f483fc45 in MYSQL_BIN_LOG::write (this=0x55f2f557d9c0 <mysql_bin_log>, event_info=event_info@entry=0x149a3d71b110, with_annotate=with_annotate@entry=0x0) at /test/11.0_opt/sql/log.cc:6829
      #11 0x000055f2f447f618 in THD::binlog_query (this=this@entry=0x1499f8000f38, qtype=qtype@entry=THD::STMT_QUERY_TYPE, query_arg=query_arg@entry=0x1499ec0083b8 "DROP EVENT `test`.`e`", query_len=query_len@entry=21, is_trans=<optimized out>, is_trans@entry=false, direct=<optimized out>, direct@entry=false, suppress_use=false, errcode=0) at /test/11.0_opt/sql/sql_class.cc:7782
      #12 0x000055f2f4579a64 in write_bin_log (is_trans=false, query_length=21, query=0x1499ec0083b8 "DROP EVENT `test`.`e`", clear_error=<optimized out>, thd=0x1499f8000f38) at /test/11.0_opt/sql/sql_table.cc:1019
      #13 write_bin_log (thd=thd@entry=0x1499f8000f38, clear_error=clear_error@entry=true, query=0x1499ec0083b8 "DROP EVENT `test`.`e`", query_length=21, is_trans=is_trans@entry=false) at /test/11.0_opt/sql/sql_table.cc:998
      #14 0x000055f2f45d8a6c in Events::drop_event (thd=thd@entry=0x1499f8000f38, dbname=dbname@entry=0x149a3d71bc88, name=0x149a3d71bc98, if_exists=if_exists@entry=false) at /test/11.0_opt/sql/sql_class.h:243
      #15 0x000055f2f45d74cd in Event_job_data::execute (this=this@entry=0x149a3d71bc40, thd=thd@entry=0x1499f8000f38, drop=<optimized out>) at /test/11.0_opt/sql/event_data_objects.cc:1545
      #16 0x000055f2f488ef19 in Event_worker_thread::run (this=0x149a3d71bd4f, thd=0x1499f8000f38, event=0x1499f4007b00) at /test/11.0_opt/sql/event_scheduler.cc:323
      #17 0x000055f2f488ef9c in event_worker_thread (arg=<optimized out>) at /test/11.0_opt/sql/event_scheduler.cc:268
      #18 0x0000149a56695b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
      #19 0x0000149a56727a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
      

      10.9.5 0225159a8d0e1260bfec7219b584523097a74d4b (Debug)

      mysqld: /test/10.9_dbg/mysys/mf_iocache.c:553: _my_b_write: Assertion `Count >= rest_length' failed.
      

      10.4 Optimized gives a different stack:

      10.4.28 111a752b968561b34a88f33052519cb989a8a90f (Optimized)

      Core was generated by `/test/MD070123-mariadb-10.4.28-linux-x86_64-opt/bin/mysqld --no-defaults --core'.
      Program terminated with signal SIGSEGV, Segmentation fault.
      #0  __memmove_avx_unaligned_erms ()
          at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:575
      [Current thread is 1 (Thread 0x14612010a640 (LWP 1599353))]
      (gdb) bt
      #0  __memmove_avx_unaligned_erms () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:575
      #1  0x0000555d334c9255 in memcpy (__len=18446650214900456104, __src=0x146120108dd0, __dest=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string_fortified.h:29
      #2  _my_b_write (info=0x555d33e322c0 <mysql_bin_log+800>, Buffer=0x146120108dd0 "\t\367\301c\242d", Count=19) at /test/10.4_opt/mysys/mf_iocache.c:599
      #3  0x0000555d330e773a in Log_event_writer::write_internal (this=0x146120108e50, pos=<optimized out>, len=19) at /test/10.4_opt/sql/log_event.cc:1603
      #4  0x0000555d330e793d in Log_event_writer::encrypt_and_write (this=0x146120108e50, pos=0x146120108dd0 "\t\367\301c\242d", len=<optimized out>) at /test/10.4_opt/sql/log_event.cc:1649
      #5  0x0000555d330e7a52 in Log_event_writer::write_header (this=<optimized out>, pos=<optimized out>, pos@entry=0x146120108dd0 "\t\367\301c\242d", len=<optimized out>, len@entry=19) at /test/10.4_opt/sql/log_event.cc:1692
      #6  0x0000555d330e829a in Log_event::write_header (this=this@entry=0x146120108f00, event_data_length=event_data_length@entry=19) at /test/10.4_opt/sql/log_event.cc:1785
      #7  0x0000555d330e8f26 in Gtid_log_event::write (this=0x146120108f00) at /test/10.4_opt/sql/log_event.cc:8074
      #8  0x0000555d330cbefd in Log_event_writer::write (ev=0x146120108f00, this=0x146120108e50) at /test/10.4_opt/sql/log_event.h:5245
      #9  MYSQL_BIN_LOG::write_event (this=this@entry=0x555d33e31fa0 <mysql_bin_log>, ev=ev@entry=0x146120108f00, cache_data=cache_data@entry=0x0, file=file@entry=0x555d33e322c0 <mysql_bin_log+800>) at /test/10.4_opt/sql/log.cc:5359
      #10 0x0000555d330ccf15 in MYSQL_BIN_LOG::write_event (ev=0x146120108f00, this=0x555d33e31fa0 <mysql_bin_log>) at /test/10.4_opt/sql/log.h:824
      #11 MYSQL_BIN_LOG::write_gtid_event (this=0x555d33e31fa0 <mysql_bin_log>, thd=0x1460cc000e88, standalone=<optimized out>, is_transactional=<optimized out>, commit_id=0) at /test/10.4_opt/sql/log.cc:6112
      #12 0x0000555d330dd1cc in MYSQL_BIN_LOG::write (this=0x555d33e31fa0 <mysql_bin_log>, event_info=event_info@entry=0x146120109320, with_annotate=with_annotate@entry=0x0) at /test/10.4_opt/sql/log.cc:6433
      #13 0x0000555d32d95fd8 in THD::binlog_query (this=this@entry=0x1460cc000e88, qtype=qtype@entry=THD::STMT_QUERY_TYPE, query_arg=query_arg@entry=0x1460d00011d8 "DROP EVENT `test`.`e`", query_len=query_len@entry=21, is_trans=<optimized out>, is_trans@entry=false, direct=<optimized out>, direct@entry=false, suppress_use=false, errcode=0) at /test/10.4_opt/sql/sql_class.cc:7422
      #14 0x0000555d32e70c09 in write_bin_log (is_trans=false, query_length=21, query=0x1460d00011d8 "DROP EVENT `test`.`e`", clear_error=<optimized out>, thd=0x1460cc000e88) at /test/10.4_opt/sql/sql_table.cc:1993
      #15 write_bin_log (thd=thd@entry=0x1460cc000e88, clear_error=clear_error@entry=true, query=0x1460d00011d8 "DROP EVENT `test`.`e`", query_length=21, is_trans=is_trans@entry=false) at /test/10.4_opt/sql/sql_table.cc:1981
      #16 0x0000555d32ec28fc in Events::drop_event (thd=thd@entry=0x1460cc000e88, dbname=dbname@entry=0x146120109d00, name=0x146120109d10, if_exists=if_exists@entry=false) at /test/10.4_opt/sql/sql_class.h:227
      #17 0x0000555d32ec1255 in Event_job_data::execute (this=this@entry=0x146120109cb0, thd=thd@entry=0x1460cc000e88, drop=<optimized out>) at /test/10.4_opt/sql/event_data_objects.cc:1522
      #18 0x0000555d33159799 in Event_worker_thread::run (this=0x146120109dcf, thd=0x1460cc000e88, event=0x1460cc000c50) at /test/10.4_opt/sql/event_scheduler.cc:313
      #19 0x0000555d3315981c in event_worker_thread (arg=<optimized out>) at /test/10.4_opt/sql/event_scheduler.cc:267
      #20 0x00001461393ecb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
      #21 0x000014613947ea00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
      

      And 10.9 debug asserts:

      10.9.5 0225159a8d0e1260bfec7219b584523097a74d4b (Debug)

      Core was generated by `/test/MD070123-mariadb-10.9.5-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
      Program terminated with signal SIGABRT, Aborted.
      #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22579856176704)
          at ./nptl/pthread_kill.c:44
      [Current thread is 1 (Thread 0x1489484e7640 (LWP 1404119))]
      (gdb) bt
      #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22579856176704) at ./nptl/pthread_kill.c:44
      #1  __pthread_kill_internal (signo=6, threadid=22579856176704) at ./nptl/pthread_kill.c:78
      #2  __GI___pthread_kill (threadid=22579856176704, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
      #3  0x0000148961439476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
      #4  0x000014896141f7f3 in __GI_abort () at ./stdlib/abort.c:79
      #5  0x000014896141f71b in __assert_fail_base (fmt=0x1489615d4150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55d7c9aaf675 "Count >= rest_length", file=0x55d7c9aaf698 "/test/10.9_dbg/mysys/mf_iocache.c", line=553, function=<optimized out>) at ./assert/assert.c:92
      #6  0x0000148961430e96 in __GI___assert_fail (assertion=assertion@entry=0x55d7c9aaf675 "Count >= rest_length", file=file@entry=0x55d7c9aaf698 "/test/10.9_dbg/mysys/mf_iocache.c", line=line@entry=553, function=function@entry=0x55d7c9aaf968 <__PRETTY_FUNCTION__.5> "_my_b_write") at ./assert/assert.c:101
      #7  0x000055d7c965f617 in _my_b_write (info=info@entry=0x55d7ca12ee40 <mysql_bin_log+928>, Buffer=0x1489484e5820 "\\\366\301c\242d", Count=19) at /test/10.9_dbg/mysys/mf_iocache.c:553
      #8  0x000055d7c965fb4c in my_b_write (Count=19, Buffer=<optimized out>, info=0x55d7ca12ee40 <mysql_bin_log+928>) at /test/10.9_dbg/include/my_sys.h:537
      #9  my_b_safe_write (info=0x55d7ca12ee40 <mysql_bin_log+928>, Buffer=<optimized out>, Count=19) at /test/10.9_dbg/mysys/mf_iocache.c:1623
      #10 0x000055d7c913f112 in Log_event_writer::write_internal (this=0x1489484e5950, pos=0x1489484e5820 "\\\366\301c\242d", len=19) at /test/10.9_dbg/sql/log_event_server.cc:808
      #11 0x000055d7c9147a62 in Log_event_writer::write_header (this=0x1489484e5950, pos=pos@entry=0x1489484e5820 "\\\366\301c\242d", len=len@entry=19) at /test/10.9_dbg/sql/log_event_server.cc:902
      #12 0x000055d7c914829c in Log_event::write_header (this=this@entry=0x1489484e5a10, event_data_length=event_data_length@entry=19) at /test/10.9_dbg/sql/log_event_server.cc:995
      #13 0x000055d7c914920c in Gtid_log_event::write (this=0x1489484e5a10) at /test/10.9_dbg/sql/log_event_server.cc:3733
      #14 0x000055d7c911cd3a in Log_event_writer::write (ev=0x1489484e5a10, this=0x1489484e5950) at /test/10.9_dbg/sql/log_event.h:5830
      #15 MYSQL_BIN_LOG::write_event (this=this@entry=0x55d7ca12eaa0 <mysql_bin_log>, ev=ev@entry=0x1489484e5a10, cache_data=cache_data@entry=0x0, file=file@entry=0x55d7ca12ee40 <mysql_bin_log+928>) at /test/10.9_dbg/sql/log.cc:5619
      #16 0x000055d7c911e9d5 in MYSQL_BIN_LOG::write_event (ev=0x1489484e5a10, this=0x55d7ca12eaa0 <mysql_bin_log>) at /test/10.9_dbg/sql/log.h:833
      #17 MYSQL_BIN_LOG::write_gtid_event (this=this@entry=0x55d7ca12eaa0 <mysql_bin_log>, thd=thd@entry=0x1488fc001388, standalone=standalone@entry=true, is_transactional=is_transactional@entry=false, commit_id=0, has_xid=has_xid@entry=false, is_ro_1pc=false) at /test/10.9_dbg/sql/log.cc:6507
      #18 0x000055d7c9132845 in MYSQL_BIN_LOG::write (this=0x55d7ca12eaa0 <mysql_bin_log>, event_info=event_info@entry=0x1489484e6020, with_annotate=with_annotate@entry=0x0) at /test/10.9_dbg/sql/log.cc:6835
      #19 0x000055d7c8cb9c69 in THD::binlog_query (this=this@entry=0x1488fc001388, qtype=qtype@entry=THD::STMT_QUERY_TYPE, query_arg=query_arg@entry=0x14890000b5c8 "DROP EVENT `test`.`e`", query_len=query_len@entry=21, is_trans=is_trans@entry=false, direct=direct@entry=false, suppress_use=false, errcode=0) at /test/10.9_dbg/sql/sql_class.cc:7788
      #20 0x000055d7c8dd90fe in write_bin_log (thd=thd@entry=0x1488fc001388, clear_error=clear_error@entry=true, query=0x14890000b5c8 "DROP EVENT `test`.`e`", query_length=21, is_trans=is_trans@entry=false) at /test/10.9_dbg/sql/sql_table.cc:1019
      #21 0x000055d7c8e49cdd in Events::drop_event (thd=thd@entry=0x1488fc001388, dbname=dbname@entry=0x1489484e6b98, name=name@entry=0x1489484e6ba8, if_exists=if_exists@entry=false) at /test/10.9_dbg/sql/sql_class.h:243
      #22 0x000055d7c8e483e2 in Event_job_data::execute (this=this@entry=0x1489484e6b50, thd=thd@entry=0x1488fc001388, drop=<optimized out>) at /test/10.9_dbg/sql/event_data_objects.cc:1545
      #23 0x000055d7c9195f09 in Event_worker_thread::run (this=this@entry=0x1489484e6c4f, thd=0x1488fc001388, event=0x1488fc000f80) at /test/10.9_dbg/sql/event_scheduler.cc:323
      #24 0x000055d7c919601f in event_worker_thread (arg=<optimized out>) at /test/10.9_dbg/sql/event_scheduler.cc:268
      #25 0x000014896148bb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
      #26 0x000014896151da00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
      

      Bug confirmed present in:
      MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.28 (dbg), 10.4.28 (opt), 10.5.19 (dbg), 10.5.19 (opt), 10.6.12 (dbg), 10.6.12 (opt), 10.7.8 (dbg), 10.7.8 (opt), 10.8.7 (dbg), 10.8.7 (opt), 10.9.5 (dbg), 10.9.5 (opt), 10.10.3 (dbg), 10.10.3 (opt), 10.11.2 (dbg), 10.11.2 (opt), 11.0.1 (dbg), 11.0.1 (opt)

      Bug (or feature/syntax) confirmed not present in:
      MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.40 (dbg), 5.7.40 (opt), 8.0.31 (dbg), 8.0.31 (opt)

      Attachments

        Issue Links

          Activity

            People

              Elkin Andrei Elkin
              Roel Roel Van de Paar
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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