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

MariaDB server is crushed after update to 10.4.13 (version before 10.3.21)

    XMLWordPrintable

    Details

      Description

      After update MariaDb server from 10.3.21 to 10.4.13 server is crashed twice in the last week.
      There are logs from journalctl

      May 28 02:55:33 db-slave mysqld: 2020-05-28 02:55:33 0x7fd1e80f4700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.4.13/storage/innobase/row/row0ins.cc line 231
      May 28 02:55:33 db-slave mysqld: InnoDB: Failing assertion: !cursor->index->is_committed()
      May 28 02:55:33 db-slave mysqld: InnoDB: We intentionally generate a memory trap.
      May 28 02:55:33 db-slave mysqld: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
      May 28 02:55:33 db-slave mysqld: InnoDB: If you get repeated assertion failures or crashes, even
      May 28 02:55:33 db-slave mysqld: InnoDB: immediately after the mysqld startup, there may be
      May 28 02:55:33 db-slave mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to
      May 28 02:55:33 db-slave mysqld: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
      May 28 02:55:33 db-slave mysqld: InnoDB: about forcing recovery.
      May 28 02:55:33 db-slave mysqld: 200528  2:55:33 [ERROR] mysqld got signal 6 ;
      May 28 02:55:33 db-slave mysqld: This could be because you hit a bug. It is also possible that this binary
      May 28 02:55:33 db-slave mysqld: or one of the libraries it was linked against is corrupt, improperly built,
      May 28 02:55:33 db-slave mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
      May 28 02:55:33 db-slave mysqld: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
      May 28 02:55:33 db-slave mysqld: We will try our best to scrape up some info that will hopefully help
      May 28 02:55:33 db-slave mysqld: diagnose the problem, but since we have already crashed,
      May 28 02:55:33 db-slave mysqld: something is definitely wrong and this may fail.
      May 28 02:55:33 db-slave mysqld: Server version: 10.4.13-MariaDB-log
      May 28 02:55:33 db-slave mysqld: key_buffer_size=134217728
      May 28 02:55:33 db-slave mysqld: read_buffer_size=131072
      May 28 02:55:33 db-slave mysqld: max_used_connections=338
      May 28 02:55:33 db-slave mysqld: max_threads=5002
      May 28 02:55:33 db-slave mysqld: thread_count=355
      May 28 02:55:33 db-slave mysqld: It is possible that mysqld could use up to
      May 28 02:55:33 db-slave mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11138886 K  bytes of memory
      May 28 02:55:33 db-slave mysqld: Hope that's ok; if not, decrease some variables in the equation.
      May 28 02:55:33 db-slave mysqld: Thread pointer: 0x7fc02c0009a8
      May 28 02:55:33 db-slave mysqld: Attempting backtrace. You can use the following information to find out
      May 28 02:55:33 db-slave mysqld: where mysqld died. If you see no messages after this, something went
      May 28 02:55:33 db-slave mysqld: terribly wrong...
      May 28 02:55:33 db-slave mysqld: stack_bottom = 0x7fd1e80f3ce0 thread_stack 0x49000
      May 28 02:55:34 db-slave mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5633b8f796ce]
      May 28 02:55:36 db-slave mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x5633b8a0ff7f]
      May 28 02:55:38 db-slave mysqld: /lib64/libpthread.so.0(+0xf5f0)[0x7fd207b505f0]
      May 28 02:55:41 db-slave mysqld: /lib64/libc.so.6(gsignal+0x37)[0x7fd205e21337]
      May 28 02:55:41 db-slave mysqld: /lib64/libc.so.6(abort+0x148)[0x7fd205e22a28]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0x5b346a)[0x5633b871346a]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb10cd4)[0x5633b8c70cd4]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb10fd3)[0x5633b8c70fd3]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb46d31)[0x5633b8ca6d31]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb4c16a)[0x5633b8cac16a]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xb22c5b)[0x5633b8c82c5b]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(+0xa66bbc)[0x5633b8bc6bbc]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x267)[0x5633b8a1b8c7]
      May 28 02:55:45 db-slave mysqld: /usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x291)[0x5633b8b181f1]
      May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x2dc)[0x5633b8b0aa0c]
      May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(+0x5ffce8)[0x5633b875fce8]
      May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(+0x7dacde)[0x5633b893acde]
      May 28 02:55:46 db-slave mysqld: /usr/sbin/mysqld(handle_rpl_parallel_thread+0x7bb)[0x5633b893d24b]
      May 28 02:55:48 db-slave mysqld: /lib64/libpthread.so.0(+0x7e65)[0x7fd207b48e65]
      May 28 02:55:51 db-slave mysqld: /lib64/libc.so.6(clone+0x6d)[0x7fd205ee988d]
      May 28 02:55:51 db-slave mysqld: Trying to get some variables.
      May 28 02:55:51 db-slave mysqld: Some pointers may be invalid and cause the dump to abort.
      May 28 02:55:51 db-slave mysqld: Query (0x7fc0d4ce590b): UPDATE ourTableName             SET `ip` = '127.0.0.1', `updatedAt` = '2020-05-28T02:55:33Z'             WHERE id = 12345678
      May 28 02:55:51 db-slave mysqld: Connection ID (thread ID): 39
      May 28 02:55:51 db-slave mysqld: Status: NOT_KILLED
      May 28 02:55:51 db-slave mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on
      May 28 02:55:51 db-slave mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
      May 28 02:55:51 db-slave mysqld: information that should help you find out what is causing the crash.
      May 28 02:55:51 db-slave mysqld: Writing a core file...
      May 28 02:55:51 db-slave mysqld: Working directory at /var/lib/mysql
      May 28 02:55:51 db-slave mysqld: Resource Limits:
      May 28 02:55:51 db-slave mysqld: Limit                     Soft Limit           Hard Limit           Units
      May 28 02:55:51 db-slave mysqld: Max cpu time              unlimited            unlimited            seconds
      May 28 02:55:51 db-slave mysqld: Max file size             unlimited            unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max data size             unlimited            unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max stack size            8388608              unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max core file size        0                    unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max resident set          unlimited            unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max processes             514547               514547               processes
      May 28 02:55:51 db-slave mysqld: Max open files            16364                16364                files
      May 28 02:55:51 db-slave mysqld: Max locked memory         65536                65536                bytes
      May 28 02:55:51 db-slave mysqld: Max address space         unlimited            unlimited            bytes
      May 28 02:55:51 db-slave mysqld: Max file locks            unlimited            unlimited            locks
      May 28 02:55:51 db-slave mysqld: Max pending signals       514547               514547               signals
      May 28 02:55:51 db-slave mysqld: Max msgqueue size         819200               819200               bytes
      May 28 02:55:51 db-slave mysqld: Max nice priority         0                    0
      May 28 02:55:51 db-slave mysqld: Max realtime priority     0                    0
      May 28 02:55:51 db-slave mysqld: Max realtime timeout      unlimited            unlimited            us
      May 28 02:55:51 db-slave mysqld: Core pattern: co...
      May 28 02:56:01 db-slave systemd: mariadb.service: main process exited, code=killed, status=6/ABRT
      May 28 02:56:01 db-slave systemd: Unit mariadb.service entered failed state.
      May 28 02:56:01 db-slave systemd: mariadb.service failed.
      May 28 02:56:05 db-slave mysqld_exporter: time="2020-05-28T02:56:05Z" level=error msg="Error pinging mysqld: dial tcp [::1]:3306: connect: connection refused" source="exporter.go:146"
      May 28 02:56:06 db-slave systemd: mariadb.service holdoff time over, scheduling restart.
      May 28 02:56:06 db-slave systemd: Stopped MariaDB 10.4.13 database server.
      May 28 02:56:06 db-slave systemd: Starting MariaDB 10.4.13 database server...
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] /usr/sbin/mysqld (mysqld 10.4.13-MariaDB-log) starting as process 25946 ...
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Warning] Could not increase number of max_open_files to more than 16364 (request: 37055)
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Using Linux native AIO
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Uses event mutexes
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Number of pools: 1
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Using SSE2 crc32 instructions
      May 28 02:56:06 db-slave mysqld: 2020-05-28  2:56:06 0 [Note] InnoDB: Initializing buffer pool, total size = 66G, instances = 24, chunk size = 128M
      May 28 02:56:09 db-slave mysqld: 2020-05-28  2:56:09 0 [Note] InnoDB: Completed initialization of buffer pool
      May 28 02:56:09 db-slave mysqld: 2020-05-28  2:56:09 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      May 28 02:56:09 db-slave mysqld: 2020-05-28  2:56:09 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=53195850341358
      May 28 02:56:10 db-slave mysqld: 2020-05-28  2:56:10 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
      May 28 02:56:10 db-slave mysqld: 2020-05-28  2:56:10 0 [Note] InnoDB: Trx id counter is 30000635124
      May 28 02:56:10 db-slave mysqld: 2020-05-28  2:56:10 0 [Note] InnoDB: Starting final batch to recover 4620 pages from redo log.
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Last binlog file './mysqld-bin.035240', position 370109787
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Rolled back recovered transaction 30000635119
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Rollback of non-prepared transactions completed
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Waiting for purge to start
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: 10.4.13 started; log sequence number 53195850342929; transaction id 30000635127
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] Plugin 'FEEDBACK' is disabled.
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [ERROR] mysqld: Plugin 'file_key_management' already installed
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] Using encryption key id 1 for temporary files
      May 28 02:56:11 db-slave mysqld: 2020-05-28  2:56:11 0 [Note] Recovering after a crash using mysqld-bin
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] Starting crash recovery...
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] Crash recovery finished.
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] Server socket created on IP: '::'.
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] Reading of all Master_info entries succeeded
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] Added new Master_info '' to hash table
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 10 [Note] Slave I/O thread: Start asynchronous replication to master 'repl@172.16.11.102:3306' in log 'mysqld-bin.001446' at position 4
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 11 [Note] Slave SQL thread initialized, starting replication in log 'mysqld-bin.001446' at position 4, relay log './mysqld-relay-bin.000001' position: 4; GTID position '0-1-1799532479,1-1-9932339280,3-3-3238391981,7-7-5053890666'
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 0 [Note] /usr/sbin/mysqld: ready for connections.
      May 28 02:56:12 db-slave mysqld: Version: '10.4.13-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
      May 28 02:56:12 db-slave mysqld: 2020-05-28  2:56:12 10 [Note] Slave I/O thread: connected to master 'user_for_replication@MASTER_IP_WAS_HERE:3306',replication starts at GTID position '1-1-9932339280,0-1-1799532479,3-3-3238391981,7-7-5053890666'
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              disc Alexandr Hacicheant
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated: