Galera crash

[jdf]

Hello,

We just migrated from a single mysql server, to a galera. Currently we have two servers with MySQL 5.5.23 & Galera 23.2.1 setup. They worked great for about a week or so, until today the cluster crashed. Restarting the primary instance brought everything back up so far. 

Can someone please assist me in determining what caused this? Thanks in advance.

Below is from the error.log

120730 11:05:02 [ERROR] WSREP: FK key set failed: 11

InnoDB: unknown error code 11

120730 11:05:02  InnoDB: Assertion failure in thread 139677169891072 in file row0mysql.c line 649

InnoDB: We intentionally generate a memory trap.

InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

InnoDB: If you get repeated assertion failures or crashes, even

InnoDB: immediately after the mysqld startup, there may be

InnoDB: corruption in the InnoDB tablespace. Please refer to

InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html

InnoDB: about forcing recovery.

16:05:02 UTC - 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.

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.

key_buffer_size=16777216

read_buffer_size=131072

max_used_connections=114

max_threads=151

thread_count=7

connection_count=7

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 346734 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0xac070b0

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 = 7f0920182e68 thread_stack 0x30000

/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x820a15]

/usr/sbin/mysqld(handle_fatal_signal+0x36a)[0x69866a]

/lib/libpthread.so.0(+0xf8f0)[0x7f09323f58f0]

/lib/libc.so.6(gsignal+0x35)[0x7f09313b5a75]

/lib/libc.so.6(abort+0x180)[0x7f09313b95c0]

/usr/sbin/mysqld[0x848c0b]

/usr/sbin/mysqld[0x84b1d4]

/usr/sbin/mysqld[0x835c13]

/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x68)[0x69d6f8]

/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x5b)[0x572bfb]

/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xa46)[0x579506]

/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x222f)[0x58bc7f]

/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0xfa)[0x58e94a]

/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1eff)[0x5917df]

/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b3)[0x592673]

/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x2c0)[0x62b230]

/usr/sbin/mysqld(handle_one_connection+0x4c)[0x62b2ac]

/lib/libpthread.so.0(+0x69ca)[0x7f09323ec9ca]

/lib/libc.so.6(clone+0x6d)[0x7f0931468cdd]

Trying to get some variables.

Some pointers may be invalid and cause the dump to abort.

Query (7f08e47e96f0): is an invalid pointer

Connection ID (thread ID): 1210755

Status: NOT_KILLED

[seppo....@codership.com]

Can you show some more log before the crash?

The problem looks to relate to foreign key constraints, can you
identify which tables were involved here? If you can spot the tables,
show the table definition of parent and child table by "SHOW CREATE
TABLE ..."
It may be that the foreign key is considerably long column.

-seppo

6

[jdf]

It appears one of our customers who uses Magento is causing this:

InnoDB: Error: record has 4411 fields
InnoDB: Error: record has 0 fields
WSREP: FK key len exceeded 0 16926752 3500
120731 11:42:25 [ERROR] WSREP: FK key set failed: 11

InnoDB: unknown error code 11

120731 11:42:25  InnoDB: Assertion failure in thread 139836464727808 in file row0mysql.c line 649

InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

16:42:25 UTC - 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.
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.

key_buffer_size=67108864
read_buffer_size=131072
max_used_connections=24
max_threads=1024
thread_count=13
connection_count=13

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2305792 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f2e2434fa80

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 = 7f2e36ce7e68 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x820a15]
/usr/sbin/mysqld(handle_fatal_signal+0x36a)[0x69866a]
/lib/libpthread.so.0(+0xf8f0)[0x7f2e7c0c58f0]
/lib/libc.so.6(gsignal+0x35)[0x7f2e7b085a75]
/lib/libc.so.6(abort+0x180)[0x7f2e7b0895c0]

/usr/sbin/mysqld[0x848c0b]
/usr/sbin/mysqld[0x84b1d4]
/usr/sbin/mysqld[0x835c13]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x68)[0x69d6f8]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x5b)[0x572bfb]
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xa46)[0x579506]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x222f)[0x58bc7f]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0xfa)[0x58e94a]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1eff)[0x5917df]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b3)[0x592673]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x2c0)[0x62b230]
/usr/sbin/mysqld(handle_one_connection+0x4c)[0x62b2ac]

/lib/libpthread.so.0(+0x69ca)[0x7f2e7c0bc9ca]
/lib/libc.so.6(clone+0x6d)[0x7f2e7b138cdd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.

Query (28161a0): INSERT INTO `sales_flat_order_item` (`order_id`, `quote_item_id`, `store_id`, `created_at`, `updated_at`, `product_id`, `product_type`, `product_options`, `weight`, `is_virtual`, `sku`, `name`, `description`, `applied_rule_ids`, `additional_data`, `is_qty_decimal`, `qty_backordered`, `qty_ordered`, `base_cost`, `price`, `base_price`, `original_price`, `base_original_price`, `tax_percent`, `tax_amount`, `base_tax_amount`, `discount_percent`, `discount_amount`, `base_discount_amount`, `row_total`, `base_row_total`, `row_weight`, `gift_message_id`, `gift_message_available`, `base_tax_before_discount`, `tax_before_discount`, `weee_tax_applied`, `weee_tax_applied_amount`, `weee_tax_applied_row_amount`, `base_weee_tax_applied_amount`, `base_weee_tax_applied_row_amount`, `weee_tax_disposition`, `weee_tax_row_disposition`, `base_weee_tax_disposition`, `base_weee_tax_row_disposition`, `price_incl_tax`, `base_price_incl_tax`, `row_total_incl_tax`, `base_row_total_incl_tax`, `hidden_tax_amount`, `base_hidden_tax_amount`
Connection ID (thread ID): 27979
Status: NOT_KILLED

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.
120731 11:42:26 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
120731 11:42:26 [Note] WSREP: wsrep_load(): Galera 23.2.0(r120) by Codership Oy <in...@codership.com> loaded succesfully.
120731 11:42:26 [Note] WSREP: Reusing existing '/var/lib/mysql//galera.cache'.
120731 11:42:26 [Note] WSREP: Passing config to GCS: gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3
120731 11:42:26 [Note] WSREP: wsrep_sst_grab()
120731 11:42:26 [Note] WSREP: Start replication
120731 11:42:26 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
120731 11:42:26 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
120731 11:42:26 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
120731 11:42:26 [Note] WSREP: protonet asio version 0
120731 11:42:26 [Note] WSREP: backend: asio
120731 11:42:26 [Note] WSREP: GMCast version 0
120731 11:42:26 [Note] WSREP: (b5ada0cd-db2e-11e1-0800-febf68ff291f, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
120731 11:42:26 [Note] WSREP: (b5ada0cd-db2e-11e1-0800-febf68ff291f, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
120731 11:42:26 [Note] WSREP: EVS version 0
120731 11:42:26 [Note] WSREP: PC version 0
120731 11:42:26 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer ''
120731 11:42:26 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,b5ada0cd-db2e-11e1-0800-febf68ff291f,1) memb {
       b5ada0cd-db2e-11e1-0800-febf68ff291f,
} joined {
} left {
} partitioned {
})
120731 11:42:26 [Note] WSREP: gcomm: connected
120731 11:42:26 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
120731 11:42:26 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
120731 11:42:26 [Note] WSREP: Opened channel 'my_wsrep_cluster'
120731 11:42:26 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 1
120731 11:42:26 [Note] WSREP: Waiting for SST to complete.
120731 11:42:26 [Note] WSREP: Starting new group from scratch: b5ae0d77-db2e-11e1-0800-d2e9aa1e82bd
120731 11:42:26 [Note] WSREP: STATE_EXCHANGE: sent state UUID: b5ae23e6-db2e-11e1-0800-3bf856ec120f
120731 11:42:26 [Note] WSREP: STATE EXCHANGE: sent state msg: b5ae23e6-db2e-11e1-0800-3bf856ec120f
120731 11:42:26 [Note] WSREP: STATE EXCHANGE: got state msg: b5ae23e6-db2e-11e1-0800-3bf856ec120f from 0 (db02.dal01)
120731 11:42:26 [Note] WSREP: Quorum results:
       version    = 2,
       component  = PRIMARY,
       conf_id    = 0,
       members    = 1/1 (joined/total),
       act_id     = 0,
       last_appl. = -1,
       protocols  = 0/3/1 (gcs/repl/appl),
       group UUID = b5ae0d77-db2e-11e1-0800-d2e9aa1e82bd
120731 11:42:26 [Note] WSREP: Flow-control interval: [8, 16]
120731 11:42:26 [Note] WSREP: Restored state OPEN -> JOINED (0)
120731 11:42:26 [Note] WSREP: Member 0 (db02.dal01) synced with group.
120731 11:42:26 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
120731 11:42:26 [Note] WSREP: New cluster view: global state: b5ae0d77-db2e-11e1-0800-d2e9aa1e82bd:0, view# 1: Primary, number of nodes: 1, my index: 0, protocol version 1
120731 11:42:26 [Note] WSREP: SST complete, seqno: 0
120731 11:42:26 InnoDB: The InnoDB memory heap is disabled
120731 11:42:26 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120731 11:42:26 InnoDB: Compressed tables use zlib 1.2.3.3
120731 11:42:26 InnoDB: Using Linux native AIO
120731 11:42:26 InnoDB: Initializing buffer pool, size = 128.0M
120731 11:42:26 InnoDB: Completed initialization of buffer pool
120731 11:42:26 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 15286934250
120731 11:42:26  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 15286943950
InnoDB: Transaction 14FBF4A4 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 14FBF600
120731 11:42:26  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Starting in background the rollback of uncommitted transactions
120731 11:42:26  InnoDB: Rollback of non-prepared transactions completed
120731 11:42:26  InnoDB: Waiting for the background threads to start
120731 11:42:27 InnoDB: 1.1.8 started; log sequence number 15286943950
120731 11:42:27  InnoDB: Starting recovery for XA transactions...
120731 11:42:27  InnoDB: Transaction 14FBF4A4 in prepared state after recovery
120731 11:42:27  InnoDB: Transaction contains changes to 1 rows
120731 11:42:27  InnoDB: 1 transactions in prepared state after recovery
120731 11:42:27 [Note] Found 1 prepared transaction(s) in InnoDB
120731 11:42:27 [Note] Event Scheduler: Loaded 0 events
120731 11:42:27 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.20'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution, wsrep_23.4.r3713
120731 11:42:27 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
120731 11:42:27 [Note] WSREP: Assign initial position for certification: 0, protocol version: 2
120731 11:42:27 [Note] WSREP: Synchronized with group, ready for connections
120731 11:42:27 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

[seppo....@codership.com]

Looks like we have worked with similar issue before. Can you please
send the output of:
mysql> SHOW CREATE TABLE sales_flat_order_item;


-seppo

Quoting jdf <jdf...@gmail.com>:

> It appears one of our customers who uses Magento is causing this:
>
>

> *InnoDB: Error: record has 4411 fields

> notification.*

[jdf]

mysql> show create table sales_flat_order_item \G;

*************************** 1. row ***************************

       Table: sales_flat_order_item

Create Table: CREATE TABLE `sales_flat_order_item` (

  `item_id` int(10) unsigned NOT NULL AUTO_INCREMENT,

  `order_id` int(10) unsigned NOT NULL DEFAULT '0',

  `parent_item_id` int(10) unsigned DEFAULT NULL,

  `quote_item_id` int(10) unsigned DEFAULT NULL,

  `store_id` smallint(5) unsigned DEFAULT NULL,

  `created_at` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',

  `updated_at` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',

  `product_id` int(10) unsigned DEFAULT NULL,

  `product_type` varchar(255) DEFAULT NULL,

  `product_options` text,

  `weight` decimal(12,4) DEFAULT '0.0000',

  `is_virtual` tinyint(1) unsigned DEFAULT NULL,

  `sku` varchar(255) NOT NULL DEFAULT '',

  `name` varchar(255) DEFAULT NULL,

  `description` text,

  `applied_rule_ids` text,

  `additional_data` text,

  `free_shipping` tinyint(1) unsigned NOT NULL DEFAULT '0',

  `is_qty_decimal` tinyint(1) unsigned DEFAULT NULL,

  `no_discount` tinyint(1) unsigned DEFAULT '0',

  `qty_backordered` decimal(12,4) DEFAULT '0.0000',

  `qty_canceled` decimal(12,4) DEFAULT '0.0000',

  `qty_invoiced` decimal(12,4) DEFAULT '0.0000',

  `qty_ordered` decimal(12,4) DEFAULT '0.0000',

  `qty_refunded` decimal(12,4) DEFAULT '0.0000',

  `qty_shipped` decimal(12,4) DEFAULT '0.0000',

  `base_cost` decimal(12,4) DEFAULT '0.0000',

  `price` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `base_price` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `original_price` decimal(12,4) DEFAULT NULL,

  `base_original_price` decimal(12,4) DEFAULT NULL,

  `tax_percent` decimal(12,4) DEFAULT '0.0000',

  `tax_amount` decimal(12,4) DEFAULT '0.0000',

  `base_tax_amount` decimal(12,4) DEFAULT '0.0000',

  `tax_invoiced` decimal(12,4) DEFAULT '0.0000',

  `base_tax_invoiced` decimal(12,4) DEFAULT '0.0000',

  `discount_percent` decimal(12,4) DEFAULT '0.0000',

  `discount_amount` decimal(12,4) DEFAULT '0.0000',

  `base_discount_amount` decimal(12,4) DEFAULT '0.0000',

  `discount_invoiced` decimal(12,4) DEFAULT '0.0000',

  `base_discount_invoiced` decimal(12,4) DEFAULT '0.0000',

  `amount_refunded` decimal(12,4) DEFAULT '0.0000',

  `base_amount_refunded` decimal(12,4) DEFAULT '0.0000',

  `row_total` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `base_row_total` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `row_invoiced` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `base_row_invoiced` decimal(12,4) NOT NULL DEFAULT '0.0000',

  `row_weight` decimal(12,4) DEFAULT '0.0000',

  `gift_message_id` int(10) DEFAULT NULL,

  `gift_message_available` int(10) DEFAULT NULL,

  `base_tax_before_discount` decimal(12,4) DEFAULT NULL,

  `tax_before_discount` decimal(12,4) DEFAULT NULL,

  `ext_order_item_id` varchar(255) DEFAULT NULL,

  `weee_tax_applied` text,

  `weee_tax_applied_amount` decimal(12,4) DEFAULT NULL,

  `weee_tax_applied_row_amount` decimal(12,4) DEFAULT NULL,

  `base_weee_tax_applied_amount` decimal(12,4) DEFAULT NULL,

  `base_weee_tax_applied_row_amount` decimal(12,4) DEFAULT NULL,

  `weee_tax_disposition` decimal(12,4) DEFAULT NULL,

  `weee_tax_row_disposition` decimal(12,4) DEFAULT NULL,

  `base_weee_tax_disposition` decimal(12,4) DEFAULT NULL,

  `base_weee_tax_row_disposition` decimal(12,4) DEFAULT NULL,

  `locked_do_invoice` tinyint(1) unsigned DEFAULT NULL,

  `locked_do_ship` tinyint(1) unsigned DEFAULT NULL,

  `price_incl_tax` decimal(12,4) DEFAULT NULL,

  `base_price_incl_tax` decimal(12,4) DEFAULT NULL,

  `row_total_incl_tax` decimal(12,4) DEFAULT NULL,

  `base_row_total_incl_tax` decimal(12,4) DEFAULT NULL,

  `hidden_tax_amount` decimal(12,4) DEFAULT NULL,

  `base_hidden_tax_amount` decimal(12,4) DEFAULT NULL,

  `hidden_tax_invoiced` decimal(12,4) DEFAULT NULL,

  `base_hidden_tax_invoiced` decimal(12,4) DEFAULT NULL,

  `hidden_tax_refunded` decimal(12,4) DEFAULT NULL,

  `base_hidden_tax_refunded` decimal(12,4) DEFAULT NULL,

  `is_nominal` int(11) NOT NULL DEFAULT '0',

  PRIMARY KEY (`item_id`),

  KEY `IDX_ORDER` (`order_id`),

  KEY `IDX_STORE_ID` (`store_id`),

  CONSTRAINT `FK_SALES_FLAT_ORDER_ITEM_PARENT` FOREIGN KEY (`order_id`) REFERENCES `sales_flat_order` (`entity_id`) ON DELETE CASCADE ON UPDATE CASCADE,

  CONSTRAINT `FK_SALES_FLAT_ORDER_ITEM_STORE` FOREIGN KEY (`store_id`) REFERENCES `core_store` (`store_id`) ON DELETE SET NULL ON UPDATE CASCADE

) ENGINE=InnoDB AUTO_INCREMENT=3808 DEFAULT CHARSET=utf8

1 row in set (0.00 sec)