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

MariaDB fails to start after update: Assertion failure in file pars0pars.cc line 818

Details

    Description

      After upgrading from MariaDB 10.1.32 to MariaDB 10.3.9 on one production server (several others did not encounter this problem), the server failed to start with the following problem:

      2018-09-26 01:40:31 0x7f1a0dc088c0 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.9/storage/innobase/pars/pars0pars.cc line 818
      InnoDB: Failing assertion: sym_node->table != NULL

      We managed to start MariaDB by using "innodb_force_recovery = 3" and move all data to other database servers. However a drop database command causes the same issue to appear, even with the recovery on 3.

      A "mysqlcheck --all-databases" did not find any issues and a mysqldump of all databases also did not cause any problems. This is the reason we think this might be a bug and not just data corruption.

      Enclosed are 2 problem traces. The MariaDB-pars0pars.cc-818-first.txt contains the problem just after starting the server in 3.1.9. The second contains the problem with innodb_force_recovery = 3 after a database drop was executed. It failed a few times after the database drop and then started again correctly.

      Attachments

        Issue Links

          Activity

            What kind of upgrade did you perform? Was it a "live" upgrade (shutdown and uninstall the old server, install the new server, and start it on the same datadir), or did you use a backup tool, e.g. XtraBackup or MariaBackup?

            elenst Elena Stepanova added a comment - What kind of upgrade did you perform? Was it a "live" upgrade (shutdown and uninstall the old server, install the new server, and start it on the same datadir), or did you use a backup tool, e.g. XtraBackup or MariaBackup?
            stijn Stijn added a comment -

            Yes it was a live upgrade, exactly like you mentioned.

            stijn Stijn added a comment - Yes it was a live upgrade, exactly like you mentioned.

            The same failure happened in buildbot (once so far):
            http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/912

            10.3 7aba6f8f8853acd18d471793f8b72aa1412b8151

            innodb_fts.sync_ddl 'innodb'             w2 [ fail ]
                    Test ended at 2018-09-22 21:25:16
             
            CURRENT_TEST: innodb_fts.sync_ddl
            mysqltest: At line 57: query 'TRUNCATE TABLE t1' failed: 2013: Lost connection to MySQL server during query
             
            The result from queries just before the failure was:
            < snip >
            DROP TABLE t1;
            SET GLOBAL debug_dbug = @save_debug;
            CREATE TABLE t1 (
            id INT AUTO_INCREMENT NOT NULL PRIMARY KEY,
            value VARCHAR(1024)
            ) ENGINE=InnoDB;
            CREATE FULLTEXT INDEX idx1 ON t1(value);
            SET GLOBAL debug_dbug = '+d,fts_instrument_sync_request,fts_instrument_write_words_before_select_index,ib_trunc_sleep_before_fts_cache_clear';
            INSERT INTO t1 (value) VALUES
            ('By default or with the IN NATURAL LANGUAGE MODE modifier'),
            ('performs a natural language search for a string'),
            ('collection is a set of one or more columns included'),
            ('returns a relevance value; that is, a similarity measure'),
            ('and the text in that row in the columns named in'),
            ('By default, the search is performed in case-insensitive'),
            ('sensitive full-text search, use a binary collation '),
            ('example, a column that uses the latin1 character'),
            ('collation of latin1_bin to make it case sensitive')
            ;
            TRUNCATE TABLE t1;
             
            More results from queries before failure can be found in /dev/shm/var/2/log/sync_ddl.log
             
             
            Server [mysqld.1 - pid: 30449, winpid: 30449, exit: 256] failed during test run
            Server log from this test:
            ----------SERVER LOG START-----------
            2018-09-22 21:25:14 0x7f772affd700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.10/storage/innobase/pars/pars0pars.cc line 818
            InnoDB: Failing assertion: sym_node->table != NULL
            InnoDB: We intentionally generate a memory trap.
            InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
            InnoDB: If you get repeated assertion failures or crashes, even
            InnoDB: immediately after the mysqld startup, there may be
            InnoDB: corruption in the InnoDB tablespace. Please refer to
            InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/
            InnoDB: about forcing recovery.
            180922 21:25:14 [ERROR] mysqld got signal 6 ;
            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 https://mariadb.com/kb/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.3.10-MariaDB-debug-log
            key_buffer_size=1048576
            read_buffer_size=131072
            max_used_connections=3
            max_threads=153
            thread_count=9
            It is possible that mysqld could use up to 
            key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63258 K  bytes of memory
            Hope that's ok; if not, decrease some variables in the equation.
             
            Thread pointer: 0x0
            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 = 0x0 thread_stack 0x49000
            /usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x562bab906cbf]
            /usr/sbin/mysqld(handle_fatal_signal+0x33e)[0x562bab238e1e]
            sigaction.c:0(__restore_rt)[0x7f7748bd35e0]
            :0(__GI_raise)[0x7f77470e01f7]
            :0(__GI_abort)[0x7f77470e18e8]
            /usr/sbin/mysqld(+0xbf324d)[0x562bab64e24d]
            /usr/sbin/mysqld(+0xac6433)[0x562bab521433]
            ut/ut0dbg.cc:62(_GLOBAL__sub_I_ut0dbg.cc)[0x562bab525c0f]
            pars/pars0pars.cc:1321(pars_insert_statement(sym_node_t*, void*, sel_node_t*))[0x562bab7c4f9e]
            innobase/pars0grm.y:375(yyparse())[0x562bab5292c5]
            fts/fts0sql.cc:184(fts_parse_sql(fts_table_t*, pars_info_t*, char const*))[0x562bab7a5a2e]
            fts/fts0fts.cc:3935(fts_write_node(trx_t*, que_fork_t**, fts_table_t*, fts_string_t*, fts_node_t*))[0x562bab7844c4]
            fts/fts0fts.cc:4070(fts_sync_index(fts_sync_t*, fts_index_cache_t*))[0x562bab78496a]
            fts/fts0fts.cc:4396(fts_sync(fts_sync_t*, bool, bool, bool))[0x562bab78e6bb]
            fts/fts0fts.cc:4481(fts_sync_table(dict_table_t*, bool, bool, bool))[0x562bab791235]
            fts/fts0opt.cc:2831(fts_optimize_sync_table(unsigned long))[0x562bab79382d]
            fts/fts0opt.cc:2945(fts_optimize_thread(void*))[0x562bab79a8dc]
            pthread_create.c:0(start_thread)[0x7f7748bcbe25]
            /lib64/libc.so.6(clone+0x6d)[0x7f77471a334d]
            The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
            information that should help you find out what is causing the crash.
            Writing a core file at /dev/shm/var/2/mysqld.1/data/
            ----------SERVER LOG END-------------
             
             
             - found 'core.30450' (0/0)
             
            Trying 'dbx' to get a backtrace
            gdb not found, cannot get the stack trace
             
            Trying 'lldb' to get a backtrace from coredump /dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/mysqld.1/data/core.30450
            Compressed file /dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/mysqld.1/data/core.30450
             - skipping '/dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/'
            

            elenst Elena Stepanova added a comment - The same failure happened in buildbot (once so far): http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/912 10.3 7aba6f8f8853acd18d471793f8b72aa1412b8151 innodb_fts.sync_ddl 'innodb' w2 [ fail ] Test ended at 2018-09-22 21:25:16   CURRENT_TEST: innodb_fts.sync_ddl mysqltest: At line 57: query 'TRUNCATE TABLE t1' failed: 2013: Lost connection to MySQL server during query   The result from queries just before the failure was: < snip > DROP TABLE t1; SET GLOBAL debug_dbug = @save_debug; CREATE TABLE t1 ( id INT AUTO_INCREMENT NOT NULL PRIMARY KEY, value VARCHAR(1024) ) ENGINE=InnoDB; CREATE FULLTEXT INDEX idx1 ON t1(value); SET GLOBAL debug_dbug = '+d,fts_instrument_sync_request,fts_instrument_write_words_before_select_index,ib_trunc_sleep_before_fts_cache_clear'; INSERT INTO t1 (value) VALUES ('By default or with the IN NATURAL LANGUAGE MODE modifier'), ('performs a natural language search for a string'), ('collection is a set of one or more columns included'), ('returns a relevance value; that is, a similarity measure'), ('and the text in that row in the columns named in'), ('By default, the search is performed in case-insensitive'), ('sensitive full-text search, use a binary collation '), ('example, a column that uses the latin1 character'), ('collation of latin1_bin to make it case sensitive') ; TRUNCATE TABLE t1;   More results from queries before failure can be found in /dev/shm/var/2/log/sync_ddl.log     Server [mysqld.1 - pid: 30449, winpid: 30449, exit: 256] failed during test run Server log from this test: ----------SERVER LOG START----------- 2018-09-22 21:25:14 0x7f772affd700 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.10/storage/innobase/pars/pars0pars.cc line 818 InnoDB: Failing assertion: sym_node->table != NULL InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/ InnoDB: about forcing recovery. 180922 21:25:14 [ERROR] mysqld got signal 6 ; 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 https://mariadb.com/kb/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.3.10-MariaDB-debug-log key_buffer_size=1048576 read_buffer_size=131072 max_used_connections=3 max_threads=153 thread_count=9 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63258 K bytes of memory Hope that's ok; if not, decrease some variables in the equation.   Thread pointer: 0x0 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 = 0x0 thread_stack 0x49000 /usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x562bab906cbf] /usr/sbin/mysqld(handle_fatal_signal+0x33e)[0x562bab238e1e] sigaction.c:0(__restore_rt)[0x7f7748bd35e0] :0(__GI_raise)[0x7f77470e01f7] :0(__GI_abort)[0x7f77470e18e8] /usr/sbin/mysqld(+0xbf324d)[0x562bab64e24d] /usr/sbin/mysqld(+0xac6433)[0x562bab521433] ut/ut0dbg.cc:62(_GLOBAL__sub_I_ut0dbg.cc)[0x562bab525c0f] pars/pars0pars.cc:1321(pars_insert_statement(sym_node_t*, void*, sel_node_t*))[0x562bab7c4f9e] innobase/pars0grm.y:375(yyparse())[0x562bab5292c5] fts/fts0sql.cc:184(fts_parse_sql(fts_table_t*, pars_info_t*, char const*))[0x562bab7a5a2e] fts/fts0fts.cc:3935(fts_write_node(trx_t*, que_fork_t**, fts_table_t*, fts_string_t*, fts_node_t*))[0x562bab7844c4] fts/fts0fts.cc:4070(fts_sync_index(fts_sync_t*, fts_index_cache_t*))[0x562bab78496a] fts/fts0fts.cc:4396(fts_sync(fts_sync_t*, bool, bool, bool))[0x562bab78e6bb] fts/fts0fts.cc:4481(fts_sync_table(dict_table_t*, bool, bool, bool))[0x562bab791235] fts/fts0opt.cc:2831(fts_optimize_sync_table(unsigned long))[0x562bab79382d] fts/fts0opt.cc:2945(fts_optimize_thread(void*))[0x562bab79a8dc] pthread_create.c:0(start_thread)[0x7f7748bcbe25] /lib64/libc.so.6(clone+0x6d)[0x7f77471a334d] The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. Writing a core file at /dev/shm/var/2/mysqld.1/data/ ----------SERVER LOG END-------------     - found 'core.30450' (0/0)   Trying 'dbx' to get a backtrace gdb not found, cannot get the stack trace   Trying 'lldb' to get a backtrace from coredump /dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/mysqld.1/data/core.30450 Compressed file /dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/mysqld.1/data/core.30450 - skipping '/dev/shm/var/2/log/innodb_fts.sync_ddl-innodb/'

            I believe that this problem was emphasized in MDEV-14585 and fixed in MDEV-12023.
            The failure in the description could also be possible in MariaDB 10.2 before the MDEV-12023 fix, because the SYS_VIRTUAL table would not exist when dropping orphan internal tables for fulltext indexes.

            With MDEV-14585, also tables whose name starts with #sql will be dropped on startup. And this would cause the reported assertion failure if any of the non-hard-coded metadata tables does not exist. On upgrade, the tables would be created a little later.

            marko Marko Mäkelä added a comment - I believe that this problem was emphasized in MDEV-14585 and fixed in MDEV-12023 . The failure in the description could also be possible in MariaDB 10.2 before the MDEV-12023 fix, because the SYS_VIRTUAL table would not exist when dropping orphan internal tables for fulltext indexes. With MDEV-14585 , also tables whose name starts with #sql will be dropped on startup. And this would cause the reported assertion failure if any of the non-hard-coded metadata tables does not exist. On upgrade, the tables would be created a little later.

            In MariaDB-pars0pars.cc-818-first.txt, InnoDB crashes on startup because a data dictionary table is not found while trying to drop a table whose name starts with #sql. This is clearly due to code that was added in MDEV-14585.

            In MariaDB-pars0pars.cc-818-second.txt, InnoDB refused to create the data dictionary tables, because innodb_force_recovery was set to 3. So, any DDL statement that would drop tables (DROP TABLE, DROP DATABASE, some ALTER TABLE or OPTIMIZE TABLE) would crash due to the missing data dictionary tables.

            I believe that both cases should be fixed by MDEV-12023.
            stijn, if you still have a copy of the dataset, could you try an upgrade to a recent 10.3 development snapshot and confirm that the problem has been fixed?

            marko Marko Mäkelä added a comment - In MariaDB-pars0pars.cc-818-first.txt , InnoDB crashes on startup because a data dictionary table is not found while trying to drop a table whose name starts with #sql . This is clearly due to code that was added in MDEV-14585 . In MariaDB-pars0pars.cc-818-second.txt , InnoDB refused to create the data dictionary tables, because innodb_force_recovery was set to 3. So, any DDL statement that would drop tables ( DROP TABLE , DROP DATABASE , some ALTER TABLE or OPTIMIZE TABLE ) would crash due to the missing data dictionary tables. I believe that both cases should be fixed by MDEV-12023 . stijn , if you still have a copy of the dataset, could you try an upgrade to a recent 10.3 development snapshot and confirm that the problem has been fixed?
            stijn Stijn added a comment -

            The upgrade to the development snapshot seems to have fixed the issue, thanks!

            stijn Stijn added a comment - The upgrade to the development snapshot seems to have fixed the issue, thanks!

            stijn, thank you for confirming that this was fixed by MDEV-12023.

            marko Marko Mäkelä added a comment - stijn , thank you for confirming that this was fixed by MDEV-12023 .

            People

              marko Marko Mäkelä
              stijn Stijn
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.