Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.2.25, 10.3.13, 10.3.14, 10.3.15, 10.3.16
-
Debian Stretch guests inside VMWare host
Linux 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64 GNU/Linux
Description
Galera cluster was perfectly fine running 10.3.12. Upgraded to 10.3.14, and nodes are failing almost instantly. Logs shows assertion failure on all nodes listed below:
2019-04-25 10:09:19 2 [Note] WSREP: Receiving IST: 2 writesets, seqnos 260448-260450
|
2019-04-25 10:09:19 0 [Note] WSREP: Receiving IST... 0.0% (0/2 events) complete.
|
2019-04-25 10:09:20 0x7f16f83ac700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.14/storage/innobase/row/row0ins.cc line 270
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
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.
|
190425 10:09:20 [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.14-MariaDB-1:10.3.14+maria~stretch-log
|
key_buffer_size=134217728
|
read_buffer_size=2097152
|
max_used_connections=0
|
max_threads=102
|
thread_count=9
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 760012 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7f16d40009a8
|
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 = 0x7f16f83abd28 thread_stack 0x49000
|
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55913783a92e]
|
/usr/sbin/mysqld(handle_fatal_signal+0x41f)[0x5591372eba5f]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0)[0x7f1700c9c0e0]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7f16ff33bfff]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f16ff33d42a]
|
/usr/sbin/mysqld(+0x49900a)[0x55913703500a]
|
/usr/sbin/mysqld(+0x988e2b)[0x559137524e2b]
|
/usr/sbin/mysqld(+0x9891b6)[0x5591375251b6]
|
/usr/sbin/mysqld(+0x9c3953)[0x55913755f953]
|
/usr/sbin/mysqld(+0x9c932d)[0x55913756532d]
|
/usr/sbin/mysqld(+0x99b374)[0x559137537374]
|
/usr/sbin/mysqld(+0x8d77a7)[0x5591374737a7]
|
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x122)[0x5591372f64e2]
|
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x2b1)[0x5591373dce01]
|
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x24f)[0x5591373cfdff]
|
/usr/sbin/mysqld(wsrep_apply_cb+0x585)[0x559137269635]
|
/usr/lib/galera/libgalera_smm.so(_ZNK6galera9TrxHandle5applyEPvPF15wsrep_cb_statusS1_PKvmjPK14wsrep_trx_metaERS6_+0xfe)[0x7f16f8dd6f6e]
|
/usr/lib/galera/libgalera_smm.so(+0x22fd56)[0x7f16f8e28d56]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM9apply_trxEPvPNS_9TrxHandleE+0x156)[0x7f16f8e2bc16]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM8recv_ISTEPv+0x2b8)[0x7f16f8e3f1a8]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM22request_state_transferEPvRK10wsrep_uuidlPKvl+0x9f1)[0x7f16f8e44bb1]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM19process_conf_changeEPvRK15wsrep_view_infoiNS_10Replicator5StateEl+0x9bd)[0x7f16f8e2fc7d]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource8dispatchEPvRK10gcs_actionRb+0x52b)[0x7f16f8e039bb]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource7processEPvRb+0x76)[0x7f16f8e04cc6]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM10async_recvEPv+0x8b)[0x7f16f8e2ee0b]
|
/usr/lib/galera/libgalera_smm.so(galera_recv+0x2b)[0x7f16f8e4ab6b]
|
/usr/sbin/mysqld(+0x6ce2c4)[0x55913726a2c4]
|
/usr/sbin/mysqld(start_wsrep_THD+0x373)[0x55913725c4c3]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4)[0x7f1700c924a4]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f16ff3f1d0f]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7f16d00143ab): UPDATE `h12_part` SET `part_json`=JSON_SET(IFNULL(NULLIF(TRIM(`part_json`), ''), '{}'), '$.core_charge', 0, '$.core_text', NULL) WHERE `part_id`=10531
|
Connection ID (thread ID): 2
|
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
|
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.
|
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(3 relates to)
Activity
Attempting to join a 10.3.13 node into the cluster, same problematic results. This time it was on FreeBSD 11.2. And once again, an UPDATE query on another node pushed to this one caused the assertion. Different backtrace, but most likely because it is built for a different OS, because error is otherwise the same.
FreeBSD 11.2-STABLE FreeBSD 11.2-STABLE #0 r325575+fc3d65faae6(HEAD): Thu Dec 20 16:12:30 EST 2018 amd64
2019-04-25 15:46:11 0 [Note] WSREP: Receiving IST... 0.0% ( 0/10 events) complete.
|
2019-04-25 15:46:11 0 [Note] /usr/local/libexec/mysqld: ready for connections.
|
Version: '10.3.13-MariaDB-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 FreeBSD Ports
|
2019-04-25 15:46:11 0x812afbf00 InnoDB: Assertion failure in file /wrkdirs/usr/ports/databases/mariadb103-server/work/mariadb-10.3.13/storage/innobase/row/row0ins.cc line 270
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
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.
|
190425 15:46:11 [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.13-MariaDB-log
|
key_buffer_size=134217728
|
read_buffer_size=2097152
|
max_used_connections=0
|
max_threads=102
|
thread_count=9
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759970 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x813216dc8
|
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 = 0x7fffdf9abf90 thread_stack 0x49000
|
0xcfb6fe <my_print_stacktrace+0x2e> at /usr/local/libexec/mysqld
|
0x837d86 <handle_fatal_signal+0x296> at /usr/local/libexec/mysqld
|
0x803579946 <pthread_sigmask+0x536> at /lib/libthr.so.3
|
0x803578eb2 <pthread_getspecific+0xe12> at /lib/libthr.so.3
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x85aa49a31): UPDATE `h12_part` SET `part_quantity`=2 WHERE `part_id`=21216 LIMIT 1
|
|
|
Connection ID (thread ID): 2
|
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
|
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.
|
The data files are corrupted:
if (!rec_get_deleted_flag(rec, rec_offs_comp(*offsets))) { |
/* We should never insert in place of a record that |
has not been delete-marked. The only exception is when
|
online CREATE INDEX copied the changes that we already
|
made to the clustered index, and completed the
|
secondary index creation before we got here. In this
|
case, the change would already be there. The CREATE
|
INDEX should be waiting for a MySQL meta-data lock
|
upgrade at least until this INSERT or UPDATE
|
returns. After that point, set_committed(true)
|
would be invoked in commit_inplace_alter_table(). */
|
ut_a(update->n_fields == 0);
|
ut_a(!cursor->index->is_committed());
|
ut_ad(!dict_index_is_online_ddl(cursor->index));
|
return(DB_SUCCESS); |
}
|
One recent explanation for this corruption could be MDEV-18272. Another one is MDEV-18981 if you used FOREIGN KEY with VIRTUAL columns.
This report is partly duplicating MDEV-9663.
Except they're not corrupt though. This ONLY happens when in a Galera cluster. On a single node outside of the cluster running 10.3.14, zero issue. Downgrading back to 10.3.12 while in a cluster, zero issue. All with the same data folder. Something broke the data during in-flight replication before it hits disk. This particular issue is specific to 10.3.13 and 10.3.14 only (possibly other recent releases of 10.x as well, I've only tested the 10.3 branch)
This is almost certainly related to MDEV-19385
When I'm back in the office, I'll attempt to test again with 10.3.15 to see if the issue is resolved.
Alright, I added a test 10.3.15 node into the otherwise stable 10.3.12 cluster. This new node had an entirely fresh data dir that was synced via SST from an existing stable node in the cluster. No applications were directly connecting to this new node at all, it only received replicated commands from other nodes in the Galera cluster. Depending on the query issued, different errors would occur, some being the assert, others being full on crashes. The rest of the existing 10.3.12 nodes continued without any issue at all.
Query that broke 10.3.15 node
2019-06-04 15:15:06 0x7fa8ec507700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.15/storage/innobase/row/row0ins.cc line 270
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
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.
|
190604 15:15:06 [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.15-MariaDB-1:10.3.15+maria~stretch-log
|
key_buffer_size=134217728
|
read_buffer_size=2097152
|
max_used_connections=1
|
max_threads=102
|
thread_count=9
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 760032 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7fa8c80009a8
|
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 = 0x7fa8ec506d28 thread_stack 0x49000
|
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x562c80b738de]
|
/usr/sbin/mysqld(handle_fatal_signal+0x3af)[0x562c8062235f]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0)[0x7fa8f56680e0]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7fa8f3c96fff]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fa8f3c9842a]
|
/usr/sbin/mysqld(+0x498cdc)[0x562c8036acdc]
|
/usr/sbin/mysqld(+0x98a4e4)[0x562c8085c4e4]
|
/usr/sbin/mysqld(+0x98a971)[0x562c8085c971]
|
/usr/sbin/mysqld(+0x9c573e)[0x562c8089773e]
|
/usr/sbin/mysqld(+0x9cb20d)[0x562c8089d20d]
|
/usr/sbin/mysqld(+0x99cce4)[0x562c8086ece4]
|
/usr/sbin/mysqld(+0x8d8bbf)[0x562c807aabbf]
|
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x122)[0x562c8062d172]
|
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x2b1)[0x562c807140f1]
|
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x24f)[0x562c807070ef]
|
/usr/sbin/mysqld(wsrep_apply_cb+0x585)[0x562c8059fe65]
|
/usr/lib/galera/libgalera_smm.so(_ZNK6galera9TrxHandle5applyEPvPF15wsrep_cb_statusS1_PKvmjPK14wsrep_trx_metaERS6_+0xfe)[0x7fa8ed732f6e]
|
/usr/lib/galera/libgalera_smm.so(+0x22fd56)[0x7fa8ed784d56]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM9apply_trxEPvPNS_9TrxHandleE+0x156)[0x7fa8ed787c16]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM11process_trxEPvPNS_9TrxHandleE+0x13e)[0x7fa8ed78a70e]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource8dispatchEPvRK10gcs_actionRb+0x1d8)[0x7fa8ed75f668]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource7processEPvRb+0x76)[0x7fa8ed760cc6]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM10async_recvEPv+0x8b)[0x7fa8ed78ae0b]
|
/usr/lib/galera/libgalera_smm.so(galera_recv+0x2b)[0x7fa8ed7a6b6b]
|
/usr/sbin/mysqld(+0x6ceaf4)[0x562c805a0af4]
|
/usr/sbin/mysqld(start_wsrep_THD+0x373)[0x562c80592cf3]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4)[0x7fa8f565e4a4]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fa8f3d4cd0f]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fa8e000df43): UPDATE `h12_invoice_part` SET `invoice_part_notes`='STRING REDACTED' WHERE `invoice_part_id`='203821'
|
Connection ID (thread ID): 2
|
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
|
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...
|
Working directory at /var/lib/mysql
|
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 8388608 unlimited bytes
|
Max core file size 0 unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 7930 7930 processes
|
Max open files 16364 16364 files
|
Max locked memory 65536 65536 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 7930 7930 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: core
|
During IST attempting to rejoin 10.3.15 to cluster:
2019-06-04 15:15:23 0 [Note] /usr/sbin/mysqld: ready for connections.
|
Version: '10.3.15-MariaDB-1:10.3.15+maria~stretch-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
|
2019-06-04 15:15:23 2 [Note] WSREP: Receiving IST: 1 writesets, seqnos 277475-277476
|
2019-06-04 15:15:23 0 [Note] WSREP: Receiving IST... 0.0% (0/1 events) complete.
|
2019-06-04 15:15:23 0 [Note] WSREP: Receiving IST...100.0% (1/1 events) complete.
|
2019-06-04 15:15:23 2 [Note] WSREP: IST received: 1f7b81f1-27af-11e8-8a7e-efbb038be1fd:277476
|
2019-06-04 15:15:23 0 [Note] WSREP: 1.3 (node2): State transfer from 2.3 (node1) complete.
|
2019-06-04 15:15:23 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 277476)
|
2019-06-04 15:15:23 0 [Note] WSREP: Member 1.3 (node2) synced with group.
|
2019-06-04 15:15:23 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 277476)
|
2019-06-04 15:15:23 2 [Note] WSREP: Synchronized with group, ready for connections
|
2019-06-04 15:15:23 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-06-04 15:15:24 0 [Note] WSREP: (2df0484d, 'tcp://0.0.0.0:4567') turning message relay requesting off
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: Unable to find a record to delete-mark
|
InnoDB: tuple DATA TUPLE: 2 fields;
|
0: SQL NULL;
|
1: len 4; hex 00031c2d; asc -;;
|
|
|
InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
|
0: SQL NULL;
|
1: len 4; hex 00030a99; asc ;;
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: page [page id: space=505, page number=36] (721 records, index id 4218).
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: Unable to find a record to delete-mark
|
InnoDB: tuple DATA TUPLE: 2 fields;
|
0: SQL NULL;
|
1: len 4; hex 00031c2d; asc -;;
|
|
|
InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
|
0: SQL NULL;
|
1: len 4; hex 00030a99; asc ;;
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: page [page id: space=505, page number=38] (721 records, index id 4219).
|
2019-06-04 15:15:24 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
|
2019-06-04 15:15:33 2 [ERROR] InnoDB: Record in index `part_core` of table `hagens_h12`.`h12_invoice_part` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL,[4] -(0x00031C2D)} at: COMPACT RECORD(info_bits=32, 2 fields): {NULL,[4] (0x00030A99)}
|
2019-06-04 15:15:33 0x7fc3c8315700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.15/storage/innobase/row/row0ins.cc line 270
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
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.
|
190604 15:15:33 [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.15-MariaDB-1:10.3.15+maria~stretch-log
|
key_buffer_size=134217728
|
read_buffer_size=2097152
|
max_used_connections=0
|
max_threads=102
|
thread_count=9
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 760032 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7fc3a40009a8
|
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 = 0x7fc3c8314d28 thread_stack 0x49000
|
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55769da788de]
|
/usr/sbin/mysqld(handle_fatal_signal+0x3af)[0x55769d52735f]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110e0)[0x7fc3d347a0e0]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7fc3d1aa8fff]
|
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fc3d1aaa42a]
|
/usr/sbin/mysqld(+0x498cdc)[0x55769d26fcdc]
|
/usr/sbin/mysqld(+0x98a4e4)[0x55769d7614e4]
|
/usr/sbin/mysqld(+0x98a971)[0x55769d761971]
|
/usr/sbin/mysqld(+0x9c573e)[0x55769d79c73e]
|
/usr/sbin/mysqld(+0x9cb20d)[0x55769d7a220d]
|
/usr/sbin/mysqld(+0x99cce4)[0x55769d773ce4]
|
/usr/sbin/mysqld(+0x8d8bbf)[0x55769d6afbbf]
|
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x122)[0x55769d532172]
|
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x2b1)[0x55769d6190f1]
|
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x24f)[0x55769d60c0ef]
|
/usr/sbin/mysqld(wsrep_apply_cb+0x585)[0x55769d4a4e65]
|
/usr/lib/galera/libgalera_smm.so(_ZNK6galera9TrxHandle5applyEPvPF15wsrep_cb_statusS1_PKvmjPK14wsrep_trx_metaERS6_+0xfe)[0x7fc3cb544f6e]
|
/usr/lib/galera/libgalera_smm.so(+0x22fd56)[0x7fc3cb596d56]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM9apply_trxEPvPNS_9TrxHandleE+0x156)[0x7fc3cb599c16]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM11process_trxEPvPNS_9TrxHandleE+0x13e)[0x7fc3cb59c70e]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource8dispatchEPvRK10gcs_actionRb+0x1d8)[0x7fc3cb571668]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera15GcsActionSource7processEPvRb+0x76)[0x7fc3cb572cc6]
|
/usr/lib/galera/libgalera_smm.so(_ZN6galera13ReplicatorSMM10async_recvEPv+0x8b)[0x7fc3cb59ce0b]
|
/usr/lib/galera/libgalera_smm.so(galera_recv+0x2b)[0x7fc3cb5b8b6b]
|
/usr/sbin/mysqld(+0x6ceaf4)[0x55769d4a5af4]
|
/usr/sbin/mysqld(start_wsrep_THD+0x373)[0x55769d497cf3]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4)[0x7fc3d34704a4]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fc3d1b5ed0f]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fc3bbfff8f3): UPDATE `h12_invoice_part` SET `part_retail`=60 WHERE (`invoice_id`=45874 AND `invoice_part_id`=203821)
|
Connection ID (thread ID): 2
|
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
|
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...
|
Working directory at /var/lib/mysql
|
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 8388608 unlimited bytes
|
Max core file size 0 unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 7930 7930 processes
|
Max open files 16364 16364 files
|
Max locked memory 65536 65536 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 7930 7930 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: core
|
Of importance:
Record in index `part_core` of table `hagens_h12`.`h12_invoice_part` was not found on update
|
`part_core` is a virtual column. It looks like possibly virtual columns are now trying to be physically replicated and failing? This does seem highly related to MDEV-19385, meaning there was more than one issue to resolve with virtual columns + instant add columns. It looks like any sort of UPDATE at all on this particular table, which has both (virtual+instant), will break.
This is very similar to MDEV-19385 except for a few minor changes.
1) The query runs perfectly on the node it was initiated on, but will fail and crash on all Galera replication nodes.
2) The query in question is an UPDATE query, rather than an INSERT query.
3) No INSTANT ADD columns needed.
Short repro:
Create a Galera cluster of at least two nodes. Once they're up, go on node 1 and run the following commands. This will crash all other nodes in the cluster.
DROP DATABASE IF EXISTS `borken`; |
|
|
CREATE DATABASE `borken`; |
|
|
USE `borken`; |
|
|
CREATE TABLE `test` ( |
`id` int AUTO_INCREMENT, |
`data` varchar(32), |
`virt` tinyint AS (1), |
PRIMARY KEY (`id`), |
KEY `virt` (`virt`) |
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; |
|
|
INSERT INTO `test` (`data`) VALUES ('broken'); |
|
|
UPDATE `test` SET `data`='MORE BROKEN'; |
Updated list of test environments
10.3.15 - Debian - asserts
10.3.15 - FreeBSD Package - asserts
10.3.15 - FreeBSD Ports - asserts
10.3.16 - Debian - asserts
10.4.5 - Debian - works as expected
I do not think that this bug depends on Galera. We have tests failing randomly, starting with version 10.2:
gcol.innodb_virtual_basic 'innodb' [ fail ] Found warnings/errors in server log file!
|
Test ended at 2019-08-20 09:40:46
|
line
|
2019-08-20 9:40:42 139672790820608 [Warning] InnoDB: Record in index `idx` of table `test`.`t` was not found on rollback, trying to insert: TUPLE (info_bits=0, 3 fields): {[100]8282828282828282828282828282828282828282828282828282828282828282828282828282828282828282828282828282(0x38323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832383238323832),[20]bbbbbbbbbbbbbbbbbbbb(0x6262626262626262626262626262626262626262),[4] (0x80000001)} at: COMPACT RECORD(info_bits=32, 3 fields): {[100]8181818181818181818181818181818181818181818181818181818181818181818181818181818181818181818181818181(0x38313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831383138313831),[20]xxxxxxxxxxxxxxxxxxxx(0x7878787878787878787878787878787878787878),[4] (0x80000001)}
|
CURRENT_TEST: gcol.innodb_virtual_basic
|
mysqltest: In included file "/mariadb/10.2o/mysql-test/suite/gcol/inc/innodb_v_large_col.inc":
|
included from /mariadb/10.2o/mysql-test/suite/gcol/t/innodb_virtual_basic.test at line 730:
|
At line 48: query 'CALL UPDATE_t()' failed: 2013: Lost connection to MySQL server during query
|
…
|
----------SERVER LOG START-----------
|
2019-08-20 17:51:56 140431740368640 [ERROR] InnoDB: tried to purge non-delete-marked record in index `idx` of table `test`.`t`: tuple: TUPLE (info_bits=0, 3 fields): {[100]8888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888(0x38383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838),[20]bbbbbbbbbbbbbbbbbbbb(0x6262626262626262626262626262626262626262),[4] (0x80000001)}, record: COMPACT RECORD(info_bits=0, 3 fields): {[100]8888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888888(0x38383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838383838),[20]bbbbbbbbbbbbbbbbbbbb(0x6262626262626262626262626262626262626262),[4] (0x80000001)}
|
mysqld: /mariadb/10.2o/storage/innobase/row/row0purge.cc:596: bool row_purge_remove_sec_if_poss_leaf(purge_node_t *, dict_index_t *, const dtuple_t *): Assertion `0' failed.
|
While these failures look different, I think that they could share the same root cause due to which the secondary index on the virtual column gets out of sync with the clustered index.
I remember that in some other bug I made the observation that indexed virtual columns do not appear to be evaluated before invoking ha_innobase::delete(). Maybe that could be explaining some of this?
I think that MDEV-17466 could be a good starting point for fixing this.
Yet another variation, now on 10.4+ it doesn't require explicit virtual columns, unique keys for long blobs do the trick.
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 (pk INT, a TEXT NOT NULL DEFAULT '', PRIMARY KEY (pk), b INT AUTO_INCREMENT, UNIQUE(b), UNIQUE (a,b)) ENGINE=InnoDB; |
REPLACE INTO t1 VALUES (0,'',NULL),(0,'',NULL); |
|
|
# Cleanup
|
DROP TABLE t1; |
|
10.4 non-debug 9a621200 |
2019-12-10 21:50:20 9 [ERROR] InnoDB: Record in index `a` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8] |(0x000000110000097C),[4] (0x80000000)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8] P(0x0000001100000950),[4] (0x80000000)}
|
2019-12-10 21:50:20 0x7f8030066700 InnoDB: Assertion failure in file /data/src/10.4/storage/innobase/row/row0ins.cc line 263
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
|
|
#6 0x000056029bd0ca7f in ut_dbg_assertion_failed (expr=expr@entry=0x56029c6a75c8 "!cursor->index->is_committed()", file=file@entry=0x56029c6a70e0 "/data/src/10.4/storage/innobase/row/row0ins.cc", line=line@entry=263) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
|
#7 0x000056029c206a10 in row_ins_sec_index_entry_by_modify (mtr=0x7f8030061960, thr=0x7f7fe40c4e68, entry=0x7f7fe4046d40, heap=0x7f7fe404d4f0, offsets_heap=<optimized out>, offsets=0x7f8030060a10, cursor=0x7f8030060a90, mode=2, flags=0) at /data/src/10.4/storage/innobase/row/row0ins.cc:263
|
#8 row_ins_sec_index_entry_low (flags=flags@entry=0, mode=mode@entry=2, index=index@entry=0x7f7fe40ca210, offsets_heap=<optimized out>, offsets_heap@entry=0x7f7fe404d070, heap=heap@entry=0x7f7fe404d4f0, entry=entry@entry=0x7f7fe4046d40, trx_id=<optimized out>, thr=0x7f7fe40c4e68) at /data/src/10.4/storage/innobase/row/row0ins.cc:3099
|
#9 0x000056029c206e7b in row_ins_sec_index_entry (index=index@entry=0x7f7fe40ca210, entry=entry@entry=0x7f7fe4046d40, thr=thr@entry=0x7f7fe40c4e68, check_foreign=check_foreign@entry=true) at /data/src/10.4/storage/innobase/row/row0ins.cc:3314
|
#10 0x000056029c2073f7 in row_ins_index_entry (thr=0x7f7fe40c4e68, entry=<optimized out>, index=<optimized out>) at /data/src/10.4/storage/innobase/row/row0ins.cc:3359
|
#11 row_ins_index_entry_step (thr=0x7f7fe40c4e68, node=<optimized out>) at /data/src/10.4/storage/innobase/row/row0ins.cc:3526
|
#12 row_ins (thr=<optimized out>, node=<optimized out>) at /data/src/10.4/storage/innobase/row/row0ins.cc:3662
|
#13 row_ins_step (thr=thr@entry=0x7f7fe40c4e68) at /data/src/10.4/storage/innobase/row/row0ins.cc:3805
|
#14 0x000056029c21621b in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x7f7fe40809a8 "", prebuilt=0x7f7fe40c43c0, ins_mode=<optimized out>) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1463
|
#15 0x000056029c168bbd in ha_innobase::write_row (this=0x7f7fe40cab80, record=0x7f7fe40809a8 "") at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:8046
|
#16 0x000056029bfe794e in handler::ha_write_row (this=0x7f7fe40cab80, buf=0x7f7fe40809a8 "") at /data/src/10.4/sql/handler.cc:6674
|
#17 0x000056029bdb3fe4 in write_record (thd=thd@entry=0x7f7fe40009a8, table=table@entry=0x7f7fe407fba8, info=info@entry=0x7f8030062880) at /data/src/10.4/sql/sql_insert.cc:1732
|
#18 0x000056029bdbb179 in mysql_insert (thd=thd@entry=0x7f7fe40009a8, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=<optimized out>, ignore=<optimized out>) at /data/src/10.4/sql/sql_insert.cc:1078
|
#19 0x000056029bde7f6c in mysql_execute_command (thd=thd@entry=0x7f7fe40009a8) at /data/src/10.4/sql/sql_parse.cc:4529
|
#20 0x000056029bdecb09 in mysql_parse (thd=thd@entry=0x7f7fe40009a8, rawbuf=<optimized out>, length=46, parser_state=parser_state@entry=0x7f80300651a0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.4/sql/sql_parse.cc:7901
|
#21 0x000056029bdeef02 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f7fe40009a8, packet=packet@entry=0x7f7fe40079d9 "REPLACE INTO t1 VALUES (0,'',NULL),(0,'',NULL)", packet_length=packet_length@entry=46, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.4/sql/sql_parse.cc:1842
|
#22 0x000056029bdf0629 in do_command (thd=0x7f7fe40009a8) at /data/src/10.4/sql/sql_parse.cc:1360
|
#23 0x000056029bebf834 in do_handle_one_connection (connect=connect@entry=0x56029de7c1d8) at /data/src/10.4/sql/sql_connect.cc:1412
|
#24 0x000056029bebf8e4 in handle_one_connection (arg=arg@entry=0x56029de7c1d8) at /data/src/10.4/sql/sql_connect.cc:1316
|
#25 0x000056029c46be84 in pfs_spawn_thread (arg=0x56029de1c178) at /data/src/10.4/storage/perfschema/pfs.cc:1862
|
#26 0x00007f8037a0b4a4 in start_thread (arg=0x7f8030066700) at pthread_create.c:456
|
#27 0x00007f8035f52d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Debug builds fail with another infamous one
|
10.4 debug 9a621200 |
2019-12-10 21:51:42 9 [ERROR] InnoDB: Record in index `a` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8] |(0x000000110000097C),[4] (0x80000000)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8] P(0x0000001100000950),[4] (0x80000000)}
|
mysqld: /data/src/10.4/storage/innobase/row/row0upd.cc:2425: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `btr_validate_index(index, 0)' failed.
|
191210 21:51:42 [ERROR] mysqld got signal 6 ;
|
|
|
#7 0x00007fc3c4b1ef12 in __GI___assert_fail (assertion=0x555af35ddcf5 "btr_validate_index(index, 0)", file=0x555af35dd558 "/data/src/10.4/storage/innobase/row/row0upd.cc", line=2425, function=0x555af35e04c0 <row_upd_sec_index_entry(upd_node_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
|
#8 0x0000555af2e018a5 in row_upd_sec_index_entry (node=0x7fc37418bfb0, thr=0x7fc37406f248) at /data/src/10.4/storage/innobase/row/row0upd.cc:2425
|
#9 0x0000555af2e0224d in row_upd_sec_step (node=0x7fc37418bfb0, thr=0x7fc37406f248) at /data/src/10.4/storage/innobase/row/row0upd.cc:2549
|
#10 0x0000555af2e0524b in row_upd (node=0x7fc37418bfb0, thr=0x7fc37406f248) at /data/src/10.4/storage/innobase/row/row0upd.cc:3327
|
#11 0x0000555af2e05691 in row_upd_step (thr=0x7fc37406f248) at /data/src/10.4/storage/innobase/row/row0upd.cc:3442
|
#12 0x0000555af2da102a in row_update_for_mysql (prebuilt=0x7fc37418b408) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1889
|
#13 0x0000555af2c00b1c in ha_innobase::delete_row (this=0x7fc37400b3c8, record=0x7fc3741a0ed0 "") at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:8972
|
#14 0x0000555af29c2526 in handler::ha_delete_row (this=0x7fc37400b3c8, buf=0x7fc3741a0ed0 "") at /data/src/10.4/sql/handler.cc:6782
|
#15 0x0000555af26092f7 in write_record (thd=0x7fc374000af0, table=0x7fc37400a560, info=0x7fc3b9ecc490) at /data/src/10.4/sql/sql_insert.cc:2007
|
#16 0x0000555af26064c7 in mysql_insert (thd=0x7fc374000af0, table_list=0x7fc374013260, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false) at /data/src/10.4/sql/sql_insert.cc:1078
|
#17 0x0000555af2654615 in mysql_execute_command (thd=0x7fc374000af0) at /data/src/10.4/sql/sql_parse.cc:4529
|
#18 0x0000555af2660dc7 in mysql_parse (thd=0x7fc374000af0, rawbuf=0x7fc374013158 "REPLACE INTO t1 VALUES (0,'',NULL),(0,'',NULL)", length=46, parser_state=0x7fc3b9ecd160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
|
#19 0x0000555af264bf6c in dispatch_command (command=COM_QUERY, thd=0x7fc374000af0, packet=0x7fc3741361b1 "REPLACE INTO t1 VALUES (0,'',NULL),(0,'',NULL)", packet_length=46, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
|
#20 0x0000555af264a5f9 in do_command (thd=0x7fc374000af0) at /data/src/10.4/sql/sql_parse.cc:1360
|
#21 0x0000555af27d30e7 in do_handle_one_connection (connect=0x555af52e7180) at /data/src/10.4/sql/sql_connect.cc:1412
|
#22 0x0000555af27d2e36 in handle_one_connection (arg=0x555af52e7180) at /data/src/10.4/sql/sql_connect.cc:1316
|
#23 0x0000555af31d50ed in pfs_spawn_thread (arg=0x555af5264870) at /data/src/10.4/storage/perfschema/pfs.cc:1862
|
#24 0x00007fc3c66944a4 in start_thread (arg=0x7fc3b9ece700) at pthread_create.c:456
|
#25 0x00007fc3c4bdbd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Elena, the issue with your last case of using an auto_increment with unique is related to the fact that virtual columns doesn't work with auto increment.
The reason is that auto_increment is updated after all virtual columns are updated.
I will fix, as part of MDEV-21606, that one will get an error if one tries to create such a table.
The additional problem in 10.4 with UNIQUE BLOB was introduced by MDEV-371 and will be addressed in MDEV-21606.
I can also reproduce a similar bug in a 10.3.13-MariaDB used as read-replica
The master server is also 10.3.13-MariaDB, however the master is working normally without problems.
Both servers the master and the replica are running in two AWS RDS instances (Both T3.medium)
The read-replica crash when attempt to operate a record into a table that contains an indexed virtual field.
The virtual field name is "register_at_year" and it has the following expression: "year(`register_at`)"
The affected table structure:
CREATE TABLE `clicks` ( |
`id` int(10) unsigned NOT NULL AUTO_INCREMENT, |
`click_id` varchar(50) COLLATE utf8mb4_unicode_ci NOT NULL, |
`product_id` int(10) unsigned DEFAULT NULL, |
`product_type` varchar(50) COLLATE utf8mb4_unicode_ci NOT NULL, |
`campaign_name` varchar(150) COLLATE utf8mb4_unicode_ci NOT NULL, |
`register_at` timestamp NOT NULL DEFAULT current_timestamp(), |
`register_at_year` smallint(4) unsigned GENERATED ALWAYS AS (year(`register_at`)) VIRTUAL, |
`created_at` timestamp NULL DEFAULT NULL, |
`updated_at` timestamp NULL DEFAULT NULL, |
`site` varchar(50) COLLATE utf8mb4_unicode_ci DEFAULT NULL, |
`market` char(3) COLLATE utf8mb4_unicode_ci DEFAULT NULL, |
PRIMARY KEY (`id`), |
UNIQUE KEY `conversioninfos_click_id_unique` (`click_id`), |
KEY `clicks_product_id_product_type_index` (`product_id`,`product_type`), |
KEY `register_at_year_index` (`register_at_year`) USING BTREE |
) ENGINE=InnoDB AUTO_INCREMENT=0 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci |
The "clicks" table can have an insert rate of more than 300 entries per hour.
The read-replica logs shows the following error:
2020-03-17 8:00:51 11 [ERROR] InnoDB: Record in index `register_at_year_index` of table `datasystem`.`clicks` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL,[4] \ (0x005C0FD6)} at: COMPACT RECORD(info_bits=32, 2 fields): {NULL,[4] \ (0x005C0ECC)}
|
2020-03-17 08:00:51 0x2b8867b46700 InnoDB: Assertion failure in file /local/p4clients/pkgbuild-7z9Zh/workspace/src/RDSMariaDB/storage/innobase/row/row0ins.cc line 270
|
InnoDB: Failing assertion: !cursor->index->is_committed()
|
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.
|
200317 8:00:51 [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.13-MariaDB
|
key_buffer_size=16777216
|
read_buffer_size=262144
|
max_used_connections=6
|
max_threads=310
|
thread_count=14
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 737516 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x2b88fec44008
|
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 = 0x2b8867b45788 thread_stack 0x40000
|
/rdsdbbin/mysql/bin/mysqld(my_print_stacktrace+0x29)[0x564ff56e28c9]
|
mysys/stacktrace.c:270(my_print_stacktrace)[0x564ff51aa07d]
|
sigaction.c:0(__restore_rt)[0x2b8868b43100]
|
:0(__GI_raise)[0x2b8868d855f7]
|
:0(__GI_abort)[0x2b8868d86ce8]
|
/rdsdbbin/mysql/bin/mysqld(+0x59c22d)[0x564ff4f0a22d]
|
ut/ut0rbt.cc:469(rbt_eject_node)[0x564ff53bd06b]
|
row/row0ins.cc:293(row_ins_sec_index_entry_by_modify)[0x564ff53bd5b4]
|
row/row0ins.cc:3363(row_ins_sec_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, bool))[0x564ff53f7c9f]
|
row/row0upd.cc:2536(row_upd_sec_index_entry)[0x564ff53fdd13]
|
row/row0upd.cc:3333(row_upd)[0x564ff53cfa0c]
|
row/row0mysql.cc:1890(row_update_for_mysql(row_prebuilt_t*))[0x564ff5311eb8]
|
handler/ha_innodb.cc:8841(ha_innobase::update_row(unsigned char const*, unsigned char const*))[0x564ff51b41d2]
|
sql/handler.cc:6317(handler::ha_update_row(unsigned char const*, unsigned char const*))[0x564ff528c9f8]
|
sql/log_event.cc:14635(Update_rows_log_event::do_exec_row(rpl_group_info*))[0x564ff5280330]
|
sql/log_event.cc:11561(Rows_log_event::do_apply_event(rpl_group_info*))[0x564ff4f423ea]
|
sql/log_event.h:1483(Log_event::apply_event(rpl_group_info*))[0x564ff4f4b8c8]
|
pthread_create.c:0(start_thread)[0x2b8868b3bdc5]
|
/lib64/libc.so.6(clone+0x6d)[0x2b8868e46c9d]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x2b88feebb61b): update `clicks` set `market` = UPPER(RIGHT(site,2)), `clicks`.`updated_at` = '2020-03-17 09:00:02' where `market` is null and `site` is not null and `site` NOT LIKE '%.com'
|
Connection ID (thread ID): 11
|
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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
|
|
|
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.
|
2020-03-17 8:01:10 0 [Warning] You need to use --log-bin to make --log-slave-updates work.
|
2020-03-17 8:01:10 0 [Note] InnoDB: Using Linux native AIO
|
2020-03-17 8:01:10 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2020-03-17 8:01:10 0 [Note] InnoDB: Uses event mutexes
|
2020-03-17 8:01:10 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2020-03-17 8:01:10 0 [Note] InnoDB: Number of pools: 1
|
2020-03-17 8:01:10 0 [Note] InnoDB: Using SSE2 crc32 instructions
|
2020-03-17 8:01:10 0 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 8, chunk size = 128M
|
2020-03-17 8:01:10 0 [Note] InnoDB: Completed initialization of buffer pool
|
2020-03-17 8:01:10 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
|
2020-03-17 8:01:10 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=38963171795
|
2020-03-17 8:01:11 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
|
2020-03-17 8:01:11 0 [Note] InnoDB: Trx id counter is 45406868
|
2020-03-17 8:01:11 0 [Note] InnoDB: Starting final batch to recover 1 pages from redo log.
|
2020-03-17 8:01:11 0 [Note] InnoDB: Last binlog file 'mysql-bin-changelog.000004', position 1065
|
2020-03-17 8:01:11 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
|
2020-03-17 8:01:11 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
|
2020-03-17 8:01:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2020-03-17 8:01:11 0 [Note] InnoDB: Setting file '/rdsdbdata/db/innodb/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2020-03-17 8:01:11 0 [Note] InnoDB: File '/rdsdbdata/db/innodb/ibtmp1' size is now 12 MB.
|
2020-03-17 8:01:11 0 [Note] InnoDB: Waiting for purge to start
|
2020-03-17 8:01:11 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2020-03-17 8:01:11 0 [Warning] InnoDB: Record in index `register_at_year_index` of table `datasystem`.`clicks` was not found on rollback, trying to insert: TUPLE (info_bits=0, 2 fields): {NULL,[4] \ (0x005C0FD6)} at: COMPACT RECORD(info_bits=32, 2 fields): {NULL,[4] \ (0x005C0ECC)}
|
2020-03-17 8:01:11 0 [Note] InnoDB: Rolled back recovered transaction 45406867
|
2020-03-17 8:01:11 0 [Note] InnoDB: Rollback of non-prepared transactions completed
|
2020-03-17 8:01:11 0 [Note] InnoDB: 10.3.13 started; log sequence number 38963172618; transaction id 45406871
|
2020-03-17 8:01:11 0 [Note] InnoDB: Loading buffer pool(s) from /rdsdbdata/db/innodb/ib_buffer_pool
|
2020-03-17 8:01:11 0 [Note] mysqld: Aria engine: starting recovery
|
recovered pages: 0% 10% 20% 30% 40% 50% 60% 70% 80% 90% 100% (0.0 seconds); tables to flush: 3 2 1 0 (0.1 seconds);
|
2020-03-17 8:01:11 0 [Note] mysqld: Aria engine: recovery done
|
2020-03-17 8:01:11 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2020-03-17 8:01:11 0 [Warning] /rdsdbbin/mysql/bin/mysqld: unknown variable 'loose-rocksdb_log_dir=/rdsdbdata/db/log'
|
2020-03-17 8:01:11 0 [Note] Recovering after a crash using tc.log
|
2020-03-17 8:01:11 0 [Note] Starting crash recovery...
|
2020-03-17 8:01:11 0 [Note] Crash recovery finished.
|
2020-03-17 8:01:11 0 [Note] Server socket created on IP: '::'.
|
2020-03-17 8:01:11 0 [Note] Reading of all Master_info entries succeded
|
2020-03-17 8:01:11 0 [Note] Added new Master_info '' to hash table
|
2020-03-17 8:01:11 0 [Warning] Recovery from master pos 4 and file mysql-bin-changelog.004025.
|
2020-03-17 8:01:11 0 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections.
|
Version: '10.3.13-MariaDB' socket: '/tmp/mysql.sock' port: 3306 Source distribution
|
2020-03-17 8:01:30 0 [Note] InnoDB: Buffer pool(s) load completed at 200317 8:01:30
|
2020-03-17 8:02:00 9 [Note] Slave I/O thread: Start asynchronous replication to master 'rdsrepladmin@XX.XX.XX.XX:3306' in log 'mysql-bin-changelog.004025' at position 4
|
2020-03-17 8:02:00 10 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin-changelog.004025' at position 4, relay log '/rdsdbdata/log/relaylog/relaylog.000001' position: 4; GTID position '0-1887754378-17553816'
|
2020-03-17 8:02:00 9 [Note] Slave I/O thread: connected to master 'rdsrepladmin@XX.XX.XX.XX:3306',replication starts at GTID position '0-1887754378-17553816'
|
I also deployed new read-replicas from with the same result.
Hello Nikita,
Thank you for working on this issue.
Changes look good.
When 10.3.14 is the only node in the cluster right after bootstrapping, all works well. As soon as a second node is added and UPDATEs start happening, this assert is triggered.
Reverted a pair of nodes to 10.3.12 with the single 10.3.14 node remaining in the cluster (3 node total cluster), all nodes seem to be accepting writes just fine. Reverted that final node back to 10.3.12 just to be on the safe side though. (EDIT: not entirely positive the .14 node was functioning properly, this wasn't tested thoroughly enough)
I've yet to try 10.3.13 to see if that is the version that introduced the issue. Also, I've only attempted to upgrade this one single cluster yet, have not tried my other clusters to see if they have the same issue.
Galera version is at 25.3.26 on the working nodes.