Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5.13
-
production
Description
| 1639639969000 | 2021-12-16 07:32:49 0x2b284df8d700 InnoDB: Assertion failure in file /local/p4clients/pkgbuild-78Qdm/workspace/src/RDSMariaDB/storage/innobase/fts/fts0que.cc line 3833 InnoDB: Failing assertion: !query->intersection 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/innodb-recovery-modes/ InnoDB: about forcing recovery. |
|
| 1639639969000 | 211216 7:32:49 [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.5.13-MariaDB-log key_buffer_size=67108864 read_buffer_size=262144 max_used_connections=112 max_threads=258 thread_count=19 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 666127 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x2b2858c55298 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 = 0x2b284df8b578 thread_stack 0x40000 |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] mysqld: Aria engine: starting recovery tables to flush: 1 0 (0.0 seconds); |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] mysqld: Aria engine: recovery done |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Uses event mutexes |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Number of pools: 1 |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Using Linux native AIO |
|
| 1639640003000 | 2021-12-16 7:33:23 0 [Note] InnoDB: Initializing buffer pool, total size = 99857989632, chunk size = 134217728 |
|
| 1639640005000 | 2021-12-16 7:33:25 0 [Note] InnoDB: Completed initialization of buffer pool |
|
| 1639640005000 | 2021-12-16 7:33:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3756849748681,3756886192973 |
|
| 1639640014000 | 2021-12-16 7:33:34 0 [Note] InnoDB: Starting final batch to recover 35903 pages from redo log. |
|
| 1639640020000 | 2021-12-16 7:33:40 0 [Note] InnoDB: To recover: 11703 pages from log |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: Last binlog file '/rdsdbdata/log/binlog/mysql-bin-changelog.158766', position 758657 |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: 128 rollback segments are active. |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: Creating shared tablespace for temporary tables |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: Setting file '/rdsdbdata/db/innodb/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: File '/rdsdbdata/db/innodb/ibtmp1' size is now 12 MB. |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: 10.5.13 started; log sequence number 3757197118152; transaction id 676200883 |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] InnoDB: Loading buffer pool(s) from /rdsdbdata/db/innodb/ib_buffer_pool |
|
| 1639640030000 | 211216 7:33:50 server_audit: MariaDB Audit Plugin version 1.4.13 STARTED. |
|
| 1639640030000 | 211216 7:33:50 server_audit: logging started to the file /rdsdbdata/log/audit/server_audit.log. |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Recovering after a crash using /rdsdbdata/log/binlog/mysql-bin-changelog |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Starting crash recovery... |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Crash recovery finished. |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Server socket created on IP: '::'. |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Warning] 'proxies_priv' entry '@% root@ip-10-36-139-116' ignored in --skip-name-resolve mode. |
|
| 1639640030000 | 2021-12-16 7:33:50 2 [Note] Event Scheduler: scheduler thread started with id 2 |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Reading of all Master_info entries succeeded |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] Added new Master_info '' to hash table |
|
| 1639640030000 | 2021-12-16 7:33:50 0 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections. Version: '10.5.13-MariaDB-log' socket: '/tmp/mysql.sock' port: 13336 managed by https://aws.amazon.com/rds/ |
|
| 1639640055000 | 2021-12-16 7:34:15 301 [Warning] Aborted connection 301 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640103000 | 2021-12-16 7:35:03 0 [Warning] Aborted connection 0 to db: 'unconnected' user: 'unauthenticated' host: 'connecting host' (Too many connections) |
|
| 1639640120000 | 2021-12-16 7:35:20 1234 [Warning] Aborted connection 1234 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640176000 | 2021-12-16 7:36:16 2131 [Warning] Aborted connection 2131 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640240000 | 2021-12-16 7:37:20 2968 [Warning] Aborted connection 2968 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640296000 | 2021-12-16 7:38:16 3876 [Warning] Aborted connection 3876 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640356000 | 2021-12-16 7:39:16 5058 [Warning] Aborted connection 5058 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640416000 | 2021-12-16 7:40:16 6865 [Warning] Aborted connection 6865 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640480000 | 2021-12-16 7:41:20 9144 [Warning] Aborted connection 9144 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640535000 | 2021-12-16 7:42:15 10758 [Warning] Aborted connection 10758 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640600000 | 2021-12-16 7:43:20 12723 [Warning] Aborted connection 12723 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640655000 | 2021-12-16 7:44:15 14355 [Warning] Aborted connection 14355 to db: 'unconnected' user: 'unauthenticated' host: '49.255.114.186' (This connection closed normally without authentication) |
|
| 1639640717000 | 2021-12-16 7:45:17 0 [Note] InnoDB: Buffer pool(s) load completed at 211216 7:45:17 |
|
|
Attachments
Issue Links
- duplicates
-
-
- Closed
-
-
MDEV-29119 Assertion failure in file fts0que.cc causes database to crash
-
- Closed
-
Activity
Can't reproduce it, as usual. Once the corruption is fixed, everything works again, until the next corruption.
This night we had another incident. A bit more information in the error log this time:
2022-01-06 0:58:09 0 [Note] InnoDB: Uses event mutexes
|
2022-01-06 0:58:09 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2022-01-06 0:58:09 0 [Note] InnoDB: Number of pools: 1
|
2022-01-06 0:58:09 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2022-01-06 0:58:10 0 [Note] InnoDB: Using Linux native AIO
|
2022-01-06 0:58:10 0 [Note] InnoDB: Initializing buffer pool, total size = 49392123904, chunk size = 134217728
|
2022-01-06 0:58:11 0 [Note] InnoDB: Completed initialization of buffer pool
|
2022-01-06 0:58:11 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1231281831980,1231281831980
|
2022-01-06 0:58:25 0 [Note] InnoDB: Transaction 2210028327 was in the XA prepared state.
|
2022-01-06 0:58:25 0 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
|
2022-01-06 0:58:25 0 [Note] InnoDB: Trx id counter is 2210028328
|
2022-01-06 0:58:25 0 [Note] InnoDB: Starting final batch to recover 178275 pages from redo log.
|
2022-01-06 0:58:26 0 [Note] InnoDB: To recover: 172806 pages from log
|
2022-01-06 0:58:41 0 [Note] InnoDB: To recover: 115444 pages from log
|
2022-01-06 0:58:56 0 [Note] InnoDB: To recover: 56420 pages from log
|
2022-01-06 0:59:11 0 [Note] InnoDB: To recover: 6918 pages from log
|
2022-01-06 0:59:15 0 [Note] InnoDB: Last binlog file '/rdsdbdata/log/binlog/mysql-bin-changelog.011521', position 538812
|
2022-01-06 0:59:15 0 [Note] InnoDB: 128 rollback segments are active.
|
2022-01-06 0:59:19 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2022-01-06 0:59:19 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2022-01-06 0:59:19 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2022-01-06 0:59:19 0 [Note] InnoDB: Setting file '/rdsdbdata/db/innodb/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2022-01-06 0:59:19 0 [Note] InnoDB: File '/rdsdbdata/db/innodb/ibtmp1' size is now 12 MB.
|
2022-01-06 0:59:19 0 [Note] InnoDB: 10.5.13 started; log sequence number 1231922881470; transaction id 2210028330
|
2022-01-06 0:59:19 0 [Note] InnoDB: Loading buffer pool(s) from /rdsdbdata/db/innodb/ib_buffer_pool
|
2022-01-06 0:59:19 0 [Note] InnoDB: Rolled back recovered transaction 2210028283
|
2022-01-06 0:59:19 0 [Note] InnoDB: Rollback of non-prepared transactions completed
|
220106 0:59:19 server_audit: MariaDB Audit Plugin version 1.4.13 STARTED.
|
220106 0:59:19 server_audit: logging started to the file /rdsdbdata/log/audit/server_audit.log.
|
2022-01-06 0:59:19 0 [Note] Recovering after a crash using /rdsdbdata/log/binlog/mysql-bin-changelog
|
2022-01-06 0:59:19 0 [Note] Starting crash recovery...
|
2022-01-06 0:59:19 0 [Note] InnoDB: Starting recovery for XA transactions...
|
2022-01-06 0:59:19 0 [Note] InnoDB: Transaction 2210028327 in prepared state after recovery
|
2022-01-06 0:59:19 0 [Note] InnoDB: Transaction contains changes to 1 rows
|
2022-01-06 0:59:19 0 [Note] InnoDB: 1 transactions in prepared state after recovery
|
2022-01-06 0:59:19 0 [Note] Found 1 prepared transaction(s) in InnoDB
|
2022-01-06 0:59:19 0 [Note] Crash recovery finished.
|
2022-01-06 0:59:19 0 [Note] Server socket created on IP: '::'.
|
2022-01-06 0:59:22 2 [Note] Event Scheduler: scheduler thread started with id 2
|
2022-01-06 0:59:22 0 [Note] Reading of all Master_info entries succeeded
|
2022-01-06 0:59:22 0 [Note] Added new Master_info '' to hash table
|
2022-01-06 0:59:22 0 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections.
|
Version: '10.5.13-MariaDB-log' socket: '/tmp/mysql.sock' port: 13336 managed by https://aws.amazon.com/rds/
|
2022-01-06 0:59:23 37 [Note] Start binlog_dump to slave_server(101), pos(mysql-bin-changelog.011521, 539295), using_gtid(0), gtid('')
|
2022-01-06 1:01:41 5454 [ERROR] [FATAL] InnoDB: Rec offset 99, cur1 offset 12190, cur2 offset 15884
|
220106 1:01:41 [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.5.13-MariaDB-log
|
key_buffer_size=67108864
|
read_buffer_size=262144
|
max_used_connections=108
|
max_threads=258
|
thread_count=56
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 666127 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x14672ae07a98
|
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 = 0x1467400f4558 thread_stack 0x40000
|
mysys/stacktrace.c:213(my_print_stacktrace)[0x561a61b1ddae]
|
sql/signal_handler.cc:222(handle_fatal_signal)[0x561a612ca7fb]
|
sigaction.c:0(__restore_rt)[0x1473611de7e0]
|
:0(__GI_raise)[0x147360e55c20]
|
:0(__GI_abort)[0x147360e570c8]
|
:0(ib::fatal::~fatal())[0x561a61971301]
|
include/mach0data.ic:84(mach_read_from_2)[0x561a61899710]
|
btr/btr0btr.cc:1381(btr_page_reorganize_low(page_cur_t*, dict_index_t*, mtr_t*) [clone .isra.64])[0x561a61977ca6]
|
btr/btr0btr.cc:1646(btr_page_reorganize(page_cur_t*, dict_index_t*, mtr_t*))[0x561a619787f7]
|
include/dict0mem.h:1840(dict_table_t::not_redundant() const)[0x561a618582d3]
|
ibuf/ibuf0ibuf.cc:3881(ibuf_insert_to_index_page)[0x561a6185dd51]
|
buf/buf0buf.cc:3382(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool))[0x561a619abbd9]
|
buf/buf0buf.cc:3464(buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool))[0x561a619abcb6]
|
include/btr0btr.h:237(btr_block_get_func(dict_index_t const&, unsigned int, unsigned long, bool, char const*, unsigned int, mtr_t*))[0x561a6197f186]
|
btr/btr0cur.cc:280(btr_cur_latch_leaves(buf_block_t*, unsigned long, btr_cur_t*, mtr_t*))[0x561a61989107]
|
btr/btr0cur.cc:1849(btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, rw_lock_t*, char const*, unsigned int, mtr_t*, unsigned long))[0x561a6198d069]
|
row/row0ins.cc:2970(row_ins_sec_index_entry_low(unsigned long, unsigned long, dict_index_t*, mem_block_info_t*, mem_block_info_t*, dtuple_t*, unsigned long, que_thr_t*))[0x561a618d24f6]
|
row/row0ins.cc:3307(row_ins_sec_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, bool))[0x561a618d9675]
|
row/row0ins.cc:3668(row_ins)[0x561a618d99a6]
|
row/row0mysql.cc:1404(row_insert_for_mysql(unsigned char const*, row_prebuilt_t*, ins_mode_t))[0x561a618ec57b]
|
handler/ha_innodb.cc:7657(ha_innobase::write_row(unsigned char const*))[0x561a618291af]
|
sql/handler.cc:7171(handler::ha_write_row(unsigned char const*))[0x561a612d5994]
|
sql/sql_insert.cc:2140(write_record(THD*, TABLE*, st_copy_info*, select_result*))[0x561a610add6e]
|
sql/sql_insert.cc:1119(mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool, select_result*))[0x561a610b497d]
|
sql/sql_parse.cc:4660(mysql_execute_command(THD*))[0x561a610e0fab]
|
sql/sql_parse.cc:8224(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x561a610e4d70]
|
sql/sql_parse.cc:1966(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x561a610dc00e]
|
sql/sql_parse.cc:1378(do_command(THD*))[0x561a610da81d]
|
sql/sql_connect.cc:1461(do_handle_one_connection(CONNECT*, bool))[0x561a611c9696]
|
sql/sql_connect.cc:1359(handle_one_connection)[0x561a611c9a04]
|
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x561a6179ac1c]
|
pthread_create.c:0(start_thread)[0x1473611d440b]
|
:0(__GI___clone)[0x147360f0f09f]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x14672ae420f0): INSERT INTO inventory_record
|
(warehouse_id, product_id, `timestamp`, date, modified, document_number, amount, purchase_price,
|
warehouse_price, reference_type, reference_id, reference_row_id,
|
source_reference_type, source_reference_id, source_reference_row_id, source_record_id,
|
pending) VALUES (19, 3764, 1641430900, '2022-01-06', 1641430900, 274000789, '-2.000000', '6.2000', '6.2000', 1, 54990, 344074, 0, 0, 0, 0, 1), (19, 3504, 1641430900, '2022-01-06', 1641430900, 274000789, '-1.000000', '4.7500', '4.7500', 1, 54990, 344075, 0, 0, 0, 0, 1)
|
|
|
Connection ID (thread ID): 5454
|
Status: NOT_KILLED
|
|
|
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=off,condition_pushdown_from_having=on,not_null_range_scan=off
|
|
|
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /rdsdbdata/db
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size unlimited unlimited bytes
|
Max core file size 0 unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes unlimited unlimited processes
|
Max open files 65535 65535 files
|
Max locked memory 65536 65536 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 254367 254367 signals
|
Max msgqueue size 819200 819200 bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
Core pattern: /rdsdbdata/tmp/core-%e-%p
|
The AWS RDS instance was again rebooting. But this time the restarts were not back to back. There was a bit uptime before restarts. I was able to create a replica of the instance, run mysqlcheck on all the inventory_record tables, find and fix corrupt tables by dropping all non-primary indexes and recreating them.
Thank you, heikilaaniste. I think that this assertion failure is specific to the SQL statement and the query plan. Can you try to provide a minimal SQL test case for reproducing this? CREATE TABLE…FULLTEXT INDEX, possibly INSERT, and SELECT (with some fulltext search operation) should be needed.
For some reason, the current SQL statement is not present in the error log output. You should be able to get the current query from a core dump, if it is possible to enable core dumps. It should be in trx->mysql_thd->query_string in InnoDB stack frames, or thd->query_string in some higher-layer stack frames.