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

crash at startup with corrupt innodb table




      When trying to start a just-upgraded 10.1.8 server, the mysqld process crashes. I have traced this down to a specific InnoDB table, and found that innodb_force_recovery value of 1 does not allow the server to start, but 2 does. That combined with the logs seems to imply the crash s in the purge process.

      I was able to recover this server by rolling back to 5.5.45 and dumping and re-importing the database that was having problems (dropping and recreating the table would have worked too I think, but I didn't know which table it was at the time). I now also believe I could have recovered by starting with innodb_force_recovery=2 and dumping the data and reimporting.

      I know corrupt data happens, but my biggest problem (and biggest fear as we move forward upgrading customers) is that 5.5.45 could handle the broken table fine, as could 10.0.22. mysqlcheck and innochecksum didn't report any errors for the broken table. Opening this ticket in hopes that it will be fixed to be a non-crasher to be more confident in future upgrades.

      I'm not 100% sure what version of MariaDB introduced this crash. I know 10.0.22 could handle the data and 10.1.4 crashed. I tried to bisect further back but I was getting download speeds of 15K/s and decided to leave it for later.

      All of my testing was done with binaries from https://downloads.mariadb.org/mariadb/+releases/, specifically mariadb-5.5.45-linux-x86_64.tar.gz, mariadb-10.0.22-linux-x86_64.tar.gz, mariadb-10.1.4-linux-x86_64.tar.gz, and mariadb-10.1.8-linux-x86_64.tar.gz.

      The database that was corrupt is Monolith.AuthSessions in this tar of mysql_data: broken table

      Logs from crash:

      2015-11-17 13:06:26 47512341515568 [Note] /opt/mysql/bin/mysqld (mysqld 10.1.8-MariaDB-log) starting as process 23384 ...
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: The InnoDB memory heap is disabled
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Memory barrier is not used
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Compressed tables use zlib 1.2.3
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Using Linux native AIO
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Using CPU crc32 instructions
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Initializing buffer pool, size = 128.0M
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Completed initialization of buffer pool
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Highest supported file format is Barracuda.
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: The log sequence numbers 1698223465 and 1698223465 in ibdata files do not match the log sequence number 1698223515 in the ib_logfiles!
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Database was not shutdown normally!
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Starting crash recovery.
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Reading tablespace information from the .ibd files...
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: Restoring possible half-written data pages
      2015-11-17 13:06:26 47512341515568 [Note] InnoDB: from the doublewrite buffer...
      2015-11-17 13:06:27 47512341515568 [Note] InnoDB: 128 rollback segment(s) are active.
      2015-11-17 13:06:27 2b3679806940 InnoDB: Assertion failure in thread 47512966687040 in file btr0cur.cc line 5341
      InnoDB: Failing assertion: rb_ctx != RB_NONE
      InnoDB: We intentionally generate a memory trap.
      InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
      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: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
      InnoDB: about forcing recovery.
      151117 13:06:27 [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 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.1.8-MariaDB-log
      It is possible that mysqld could use up to
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 13470094 K bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.

      Thread pointer: 0x0x0
      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 0x48000
      2015-11-17 13:06:27 47512341515568 [Note] InnoDB: Waiting for purge to start
      2015-11-17 13:06:27 47512341515568 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 1698223515
      2015-11-17 13:06:27 47512341515568 [Note] Plugin 'FEEDBACK' is disabled.
      2015-11-17 13:06:27 47512341515568 [Note] Recovering after a crash using tc.log
      2015-11-17 13:06:27 47512341515568 [Note] Starting crash recovery...
      2015-11-17 13:06:27 47512341515568 [Note] Crash recovery finished.
      2015-11-17 13:06:27 47512987666752 [Note] InnoDB: Dumping buffer pool(s) not yet started
      2015-11-17 13:06:27 47512341515568 [Note] Server socket created on IP: '::'.
      2015-11-17 13:06:27 47512341515568 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
      2015-11-17 13:06:27 47512341515568 [Note] Event Scheduler: Loaded 0 events
      2015-11-17 13:06:27 47513019758912 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
      ERROR: 1146 Table 'Monolith.AutoIncrementResetTables' doesn't exist
      2015-11-17 13:06:27 47512341515568 [Note] /opt/monolith/vendor/mysql/bin/mysqld: ready for connections.
      Version: '10.1.8-MariaDB-log' socket: '/tmp/mysql.sock' port: 3306 MariaDB Server
      btr/btr0cur.cc:5470(btr_free_externally_stored_field(dict_index_t*, unsigned char*, unsigned char const*, unsigned long const*, page_zip_des_t*, unsigned long, trx_rb_ctx, mtr_t*))[0xa0e9d3]
      trx/trx0purge.cc:1253(trx_purge(unsigned long, unsigned long, bool))[0x9dba74]
      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.
      151117 13:06:27 mysqld_safe Number of processes running now: 0
      151117 13:06:27 mysqld_safe mysqld restarted




            Unassigned Unassigned
            jetmore John Jetmore
            0 Vote for this issue
            2 Start watching this issue



              Git Integration

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