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

Crash on recovery, assert "page_offset(rec) <= page_header_get_field(page, PAGE_HEAP_TOP)" fail

    XMLWordPrintable

    Details

      Description

      5.5.60 server segfaults on start after suffering a power outage

      5.5.60 release mariadb-server-5.5.60-1.el7_5.x86_64 centos

      mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
      [Note] /usr/libexec/mysqld (mysqld 5.5.60-MariaDB) starting as process 1711 ...
      InnoDB: The InnoDB memory heap is disabled
      InnoDB: Mutexes and rw_locks use GCC atomic builtins
      InnoDB: Compressed tables use zlib 1.2.7
      InnoDB: Using Linux native AIO
      InnoDB: Initializing buffer pool, size = 128.0M
      InnoDB: Completed initialization of buffer pool
      InnoDB: highest supported file format is Barracuda.
      InnoDB: Starting crash recovery from checkpoint LSN=616986210718
      InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
      InnoDB: Starting final batch to recover 10 pages from redo log
      [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: 5.5.60-MariaDB
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=0
      max_threads=153
      thread_count=0
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 466718 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 0x48000
      /usr/libexec/mysqld(my_print_stacktrace+0x3d)[0x56094e0b5cbd]
      /usr/libexec/mysqld(handle_fatal_signal+0x515)[0x56094dcca4a5]
      sigaction.c:0(__restore_rt)[0x7fac5bb8b5d0]
      /usr/libexec/mysqld(+0x81ff4d)[0x56094e045f4d]
      /usr/libexec/mysqld(+0x8213f6)[0x56094e0473f6]
      /usr/libexec/mysqld(+0x8047ac)[0x56094e02a7ac]
      /usr/libexec/mysqld(+0x806876)[0x56094e02c876]
      /usr/libexec/mysqld(+0x786fe9)[0x56094dfacfe9]
      /usr/libexec/mysqld(+0x7c93c3)[0x56094dfef3c3]
      /usr/libexec/mysqld(+0x730868)[0x56094df56868]
      pthread_create.c:0(start_thread)[0x7fac5bb83dd5]
      /lib64/libc.so.6(clone+0x6d)[0x7fac5a37d02d]
      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.
      

      Reproduces on 10.1 on Ubuntu 16.04 with the same data dir

      10.1 release 10.1.44-MariaDB-1~xenial ubuntu

      (gdb) r
      Starting program: /usr/sbin/mysqld --user=mysql
      [Thread debugging using libthread_db enabled]
      Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
      2020-04-26 21:23:51 140737353480448 [Note] /usr/sbin/mysqld (mysqld 10.1.44-MariaDB-1~xenial) starting as process 9675 ...
      [New Thread 0x7fffefbff700 (LWP 9679)]
      [New Thread 0x7fffddfff700 (LWP 9680)]
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: The InnoDB memory heap is disabled
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Compressed tables use zlib 1.2.8
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Using Linux native AIO
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Using SSE crc32 instructions
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Initializing buffer pool, size = 256.0M
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Completed initialization of buffer pool
      [New Thread 0x7fffca7ff700 (LWP 9681)]
      [New Thread 0x7fffc9ffe700 (LWP 9682)]
      [New Thread 0x7fffc97fd700 (LWP 9683)]
      [New Thread 0x7fffc8ffc700 (LWP 9684)]
      [New Thread 0x7fffc87fb700 (LWP 9685)]
      [New Thread 0x7fffc7ffa700 (LWP 9686)]
      [New Thread 0x7fffc77f9700 (LWP 9687)]
      [New Thread 0x7fffc6ff8700 (LWP 9688)]
      [New Thread 0x7fffc67f7700 (LWP 9689)]
      [New Thread 0x7fffc5ff6700 (LWP 9690)]
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Highest supported file format is Barracuda.
      [New Thread 0x7fffc43ff700 (LWP 9691)]
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Starting crash recovery from checkpoint LSN=616986210718
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
      [New Thread 0x7fffc3bfe700 (LWP 9692)]
      2020-04-26 21:23:51 140737353480448 [Note] InnoDB: Starting final batch to recover 10 pages from redo log
       
      Thread 8 "mysqld" received signal SIGSEGV, Segmentation fault.
      

      A 10.1 debug build shows an assertion failure

      10.1 debug 5d856760fb3941b4a36cc484e28c500236c45ac1 ubuntu

      (gdb) r
      Starting program: /usr/sbin/mysqld --user=mysql
      [Thread debugging using libthread_db enabled]
      Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
      2020-04-26 20:39:38 140737354045248 [Note] /usr/sbin/mysqld (mysqld 10.1.45-MariaDB-debug) starting as process 9611 ...
      2020-04-26 20:39:38 140737354045248 [Warning] You have enabled the binary log, but you haven't set server-id to a non-zero value: we force server id to 1; updates will be logged to the binary log, but connections from slaves will not be accepted.
      [New Thread 0x7ffff20bc700 (LWP 9615)]
      2020-04-26 20:39:38 140737354045248 [ERROR] mysqld: file-key-management-filename is not set
      2020-04-26 20:39:38 140737354045248 [ERROR] Plugin 'file_key_management' init function returned error.
      2020-04-26 20:39:38 140737354045248 [ERROR] Plugin 'file_key_management' registration as a ENCRYPTION failed.
      [New Thread 0x7fffdd757700 (LWP 9616)]
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: The InnoDB memory heap is disabled
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Compressed tables use zlib 1.2.8
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Using SSE crc32 instructions
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Initializing buffer pool, size = 256.0M
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Completed initialization of buffer pool
      [New Thread 0x7fffc6bdf700 (LWP 9617)]
      [New Thread 0x7fffc63de700 (LWP 9618)]
      [New Thread 0x7fffc5bdd700 (LWP 9619)]
      [New Thread 0x7fffc53dc700 (LWP 9620)]
      [New Thread 0x7fffc4bdb700 (LWP 9621)]
      [New Thread 0x7fffc43da700 (LWP 9622)]
      [New Thread 0x7fffc3bd9700 (LWP 9623)]
      [New Thread 0x7fffc33d8700 (LWP 9624)]
      [New Thread 0x7fffc2bd7700 (LWP 9625)]
      [New Thread 0x7fffc23d6700 (LWP 9626)]
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Highest supported file format is Barracuda.
      [New Thread 0x7fffc179c700 (LWP 9627)]
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Starting crash recovery from checkpoint LSN=616986210718
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
      [New Thread 0x7fffc0f9b700 (LWP 9628)]
      2020-04-26 20:39:39 140737354045248 [Note] InnoDB: Starting final batch to recover 10 pages from redo log
      2020-04-26 20:39:39 7fffc4bdb700  InnoDB: Assertion failure in thread 140736494155520 in file page0page.ic line 664
      InnoDB: Failing assertion: page_offset(rec) <= page_header_get_field(page, PAGE_HEAP_TOP)
      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: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
      InnoDB: about forcing recovery.
       
      Thread 8 "mysqld" received signal SIGABRT, Aborted.
      

      Let me know if you need more logs, bt full or ssh access to an instance with the data dir.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              attila Attila Molnar
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated: