Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC

Percona XtraDBCluster

Bug #1049105 reported by Azigui on 2012-09-11

This bug affects 3 people

Affects		Status	Importance	Assigned to	Milestone
	Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC	Invalid	Undecided	Unassigned

Bug Description

Hi,

I have a big problem since I update my Percona 5.5.24 to 5.5.27:
Error message in second and third node node is :

invoke-rc.d: initscript mysql, action "start" failed.
dpkg: error processing percona-xtradb-cluster-server-5.5 (--configure):
subprocess installed post-installation script returned error exit status 1
configured to not write apport reports
Errors were encountered while processing:
percona-xtradb-cluster-server-5.5
E: Sub-process /usr/bin/dpkg returned an error code (1)

the error log in mysql :

120911 13:57:14 [ERROR] WSREP: gcs/src/gcs_backend.c:gcs_backend_init():87: Invalid backend URI: 0
120911 13:57:14 [ERROR] WSREP: gcs/src/gcs_core.c:gcs_core_open():202: Failed to initialize backend using '0': -22 (Invalid argument)
120911 13:57:14 [ERROR] WSREP: gcs/src/gcs.c:gcs_open():1290: Failed to open channel 'my_wsrep_cluster' at '0': -22 (Invalid argument)
120911 13:57:14 [ERROR] WSREP: gcs connect failed: Invalid argument
120911 13:57:14 [ERROR] WSREP: wsrep::connect() failed: 6
120911 13:57:14 [ERROR] Aborting

And syslog :

Sep 11 13:56:44 t2-mysql02 mysqld_safe[10491]: ERROR: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ALTER TABLE user ADD column Show_view_priv enum('N','Y') CHARACTER SET utf8 NOT ' at line 1
Sep 11 13:56:44 t2-mysql02 mysqld_safe[10491]: 120911 13:56:44 [ERROR] Aborting
Sep 11 13:56:44 t2-mysql02 mysqld_safe[10491]:
Sep 11 13:56:44 t2-mysql02 mysqld_safe[10491]: 120911 13:56:44 [Note] WSREP: Service disconnected.
Sep 11 13:56:45 t2-mysql02 mysqld_safe[10491]: 120911 13:56:45 [Note] WSREP: Some threads may fail to exit.
Sep 11 13:56:45 t2-mysql02 mysqld_safe[10491]: 120911 13:56:45 InnoDB: Starting shutdown...
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10491]: 120911 13:56:48 InnoDB: Shutdown completed; log sequence number 2549519372
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10491]: 120911 13:56:48 [Note] /usr/sbin/mysqld: Shutdown complete
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10491]:
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Warning] option 'wsrep_max_ws_rows': unsigned value 67108864 adjusted to 1048576
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Note] Flashcache bypass: disabled
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Note] Flashcache setup error is : ioctl failed
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]:
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Note] WSREP: Read nil XID from storage engines, skipping position init
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Note] WSREP: wsrep_load(): loading provider library 'none'
Sep 11 13:56:48 t2-mysql02 kernel: [11361.879267] mysqld: sending ioctl 4004fecd to a partition!
Sep 11 13:56:48 t2-mysql02 kernel: [11361.879272] mysqld: sending ioctl 4004fecd to a partition!
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 [Note] Plugin 'FEDERATED' is disabled.
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: The InnoDB memory heap is disabled
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: Mutexes and rw_locks use GCC atomic builtins
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: Compressed tables use zlib 1.2.3
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: Using Linux native AIO
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: Initializing buffer pool, size = 1.0G
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: Completed initialization of buffer pool
Sep 11 13:56:48 t2-mysql02 mysqld_safe[10544]: 120911 13:56:48 InnoDB: highest supported file format is Barracuda.
Sep 11 13:56:53 t2-mysql02 mysqld_safe[10544]: 120911 13:56:53 InnoDB: Waiting for the background threads to start
Sep 11 13:56:54 t2-mysql02 mysqld_safe[10544]: 120911 13:56:54 Percona XtraDB (http://www.percona.com) 1.1.8-rel28.1 started; log sequence number 2549519372
Sep 11 13:56:54 t2-mysql02 mysqld_safe[10544]: 120911 13:56:54 [Note] WSREP: Service disconnected.
Sep 11 13:56:55 t2-mysql02 mysqld_safe[10544]: 120911 13:56:55 [Note] WSREP: Some threads may fail to exit.
Sep 11 13:56:55 t2-mysql02 mysqld_safe[10544]: 120911 13:56:55 InnoDB: Starting shutdown...
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10544]: 120911 13:56:58 InnoDB: Shutdown completed; log sequence number 2549519372
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Warning] option 'wsrep_max_ws_rows': unsigned value 67108864 adjusted to 1048576
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Note] Flashcache bypass: disabled
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Note] Flashcache setup error is : ioctl failed
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]:
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Note] WSREP: Read nil XID from storage engines, skipping position init
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Note] WSREP: wsrep_load(): loading provider library 'none'
Sep 11 13:56:58 t2-mysql02 kernel: [11371.684835] mysqld: sending ioctl 4004fecd to a partition!
Sep 11 13:56:58 t2-mysql02 kernel: [11371.684839] mysqld: sending ioctl 4004fecd to a partition!
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 [Note] Plugin 'FEDERATED' is disabled.
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: The InnoDB memory heap is disabled
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: Mutexes and rw_locks use GCC atomic builtins
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: Compressed tables use zlib 1.2.3
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: Using Linux native AIO
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: Initializing buffer pool, size = 1.0G
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: Completed initialization of buffer pool
Sep 11 13:56:58 t2-mysql02 mysqld_safe[10597]: 120911 13:56:58 InnoDB: highest supported file format is Barracuda.
Sep 11 13:57:02 t2-mysql02 mysqld_safe[10597]: 120911 13:57:02 InnoDB: Waiting for the background threads to start
Sep 11 13:57:03 t2-mysql02 mysqld_safe[10597]: 120911 13:57:03 Percona XtraDB (http://www.percona.com) 1.1.8-rel28.1 started; log sequence number 2549519372
Sep 11 13:57:03 t2-mysql02 mysqld_safe[10597]: ERROR: 1050 Table 'plugin' already exists
Sep 11 13:57:03 t2-mysql02 mysqld_safe[10597]: 120911 13:57:03 [ERROR] Aborting
Sep 11 13:57:03 t2-mysql02 mysqld_safe[10597]:
Sep 11 13:57:03 t2-mysql02 mysqld_safe[10597]: 120911 13:57:03 [Note] WSREP: Service disconnected.
Sep 11 13:57:04 t2-mysql02 mysqld_safe[10597]: 120911 13:57:04 [Note] WSREP: Some threads may fail to exit.
Sep 11 13:57:04 t2-mysql02 mysqld_safe[10597]: 120911 13:57:04 InnoDB: Starting shutdown...
Sep 11 13:57:07 t2-mysql02 mysqld_safe[10597]: 120911 13:57:07 InnoDB: Shutdown completed; log sequence number 2549519372
Sep 11 13:57:07 t2-mysql02 mysqld_safe[10597]: 120911 13:57:07 [Note] /usr/sbin/mysqld: Shutdown complete

Sep 11 14:14:37 t2-mysql02 /etc/init.d/mysql[3676]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Sep 11 14:14:37 t2-mysql02 /etc/init.d/mysql[3676]: #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
Sep 11 14:14:37 t2-mysql02 /etc/init.d/mysql[3676]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
Sep 11 14:14:37 t2-mysql02 /etc/init.d/mysql[3676]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!

Alexey Kopytov (akopytov) on 2012-09-11

affects:

percona-server → percona-xtradb-cluster

Revision history for this message

Alex Yurchenko (ayurchen) wrote on 2012-09-11:

what is in wsrep_cluster_address and/or wsrep_urls in my.cnf?

Revision history for this message

Jervin R (revin) wrote on 2012-12-06:

Download full text (11.7 KiB)

This also affects Precise 12.04 up to PXC 5.5.28 - the problem I think is how the deb package handles reconfiguration at different times. See my log below:

root@ubuntu:~/Downloads/PXDBC5528# cat /var/lib/mysql/error.log
121205 19:21:09 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:09 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:09 [Note] WSREP: Service disconnected.
121205 19:21:10 [Note] WSREP: Some threads may fail to exit.
121205 19:21:10 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:10 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:10 [Note] WSREP: Service disconnected.
121205 19:21:11 [Note] WSREP: Some threads may fail to exit.
121205 19:21:11 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:11 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:11 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:11 InnoDB: The InnoDB memory heap is disabled
121205 19:21:11 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:11 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:11 InnoDB: Using Linux native AIO
121205 19:21:11 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:11 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file /var/lib/mysql/innodb/ibdata1 did not exist:
InnoDB: a new database to be created!
121205 19:21:11 InnoDB: Setting file /var/lib/mysql/innodb/ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
121205 19:21:11 InnoDB: Log file /var/lib/mysql/data/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /var/lib/mysql/data/ib_logfile0 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
121205 19:21:12 InnoDB: Log file /var/lib/mysql/data/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /var/lib/mysql/data/ib_logfile1 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: 127 rollback segment(s) active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
121205 19:21:13 InnoDB: Waiting for the background threads to start
121205 19:21:14 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 0
121205 19:21:14 [Note] WSREP: Service disconnected.
121205 19:21:15 [Note] WSREP: Some threads may fail to exit.
121205 19:21:15 InnoDB: Starting shutdown...
121205 19:21:18 InnoDB: Shutdown completed; log sequence number 1597945
121205 19:21:18 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:18 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:18 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:18 InnoDB: The InnoDB memory heap is disabled
121205 19:21:18 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:18 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:18 InnoDB:...

This also affects Precise 12.04 up to PXC 5.5.28 - the problem I think is how the deb package handles reconfiguration at different times. See my log below:

root@ubuntu:~/Downloads/PXDBC5528# cat /var/lib/mysql/error.log 
121205 19:21:09 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:09 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:09 [Note] WSREP: Service disconnected.
121205 19:21:10 [Note] WSREP: Some threads may fail to exit.
121205 19:21:10 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:10 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:10 [Note] WSREP: Service disconnected.
121205 19:21:11 [Note] WSREP: Some threads may fail to exit.
121205 19:21:11 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:11 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:11 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:11 InnoDB: The InnoDB memory heap is disabled
121205 19:21:11 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:11 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:11 InnoDB: Using Linux native AIO
121205 19:21:11 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:11 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file /var/lib/mysql/innodb/ibdata1 did not exist:
InnoDB: a new database to be created!
121205 19:21:11  InnoDB: Setting file /var/lib/mysql/innodb/ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
121205 19:21:11  InnoDB: Log file /var/lib/mysql/data/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /var/lib/mysql/data/ib_logfile0 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
121205 19:21:12  InnoDB: Log file /var/lib/mysql/data/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /var/lib/mysql/data/ib_logfile1 size to 256 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: 127 rollback segment(s) active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
121205 19:21:13  InnoDB: Waiting for the background threads to start
121205 19:21:14 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 0
121205 19:21:14 [Note] WSREP: Service disconnected.
121205 19:21:15 [Note] WSREP: Some threads may fail to exit.
121205 19:21:15  InnoDB: Starting shutdown...
121205 19:21:18  InnoDB: Shutdown completed; log sequence number 1597945
121205 19:21:18 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:18 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:18 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:18 InnoDB: The InnoDB memory heap is disabled
121205 19:21:18 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:18 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:18 InnoDB: Using Linux native AIO
121205 19:21:18 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:18 InnoDB: Completed initialization of buffer pool
121205 19:21:18 InnoDB: highest supported file format is Barracuda.
121205 19:21:18  InnoDB: Waiting for the background threads to start
121205 19:21:19 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 1597945
ERROR: 1064  You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ALTER TABLE user ADD column Show_view_priv enum('N','Y') CHARACTER SET utf8 NOT ' at line 1
121205 19:21:19 [ERROR] Aborting

121205 19:21:19 [Note] WSREP: Service disconnected.
121205 19:21:20 [Note] WSREP: Some threads may fail to exit.
121205 19:21:20  InnoDB: Starting shutdown...
121205 19:21:23  InnoDB: Shutdown completed; log sequence number 1597945
121205 19:21:23 [Note] /usr/sbin/mysqld: Shutdown complete

121205 19:21:23 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:23 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:23 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:23 InnoDB: The InnoDB memory heap is disabled
121205 19:21:23 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:23 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:23 InnoDB: Using Linux native AIO
121205 19:21:23 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:23 InnoDB: Completed initialization of buffer pool
121205 19:21:23 InnoDB: highest supported file format is Barracuda.
121205 19:21:23  InnoDB: Waiting for the background threads to start
121205 19:21:24 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 1597945
121205 19:21:24 [Note] WSREP: Service disconnected.
121205 19:21:25 [Note] WSREP: Some threads may fail to exit.
121205 19:21:25  InnoDB: Starting shutdown...
121205 19:21:28  InnoDB: Shutdown completed; log sequence number 1597945
121205 19:21:28 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:28 [Note] WSREP: wsrep_load(): loading provider library 'none'
121205 19:21:28 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:28 InnoDB: The InnoDB memory heap is disabled
121205 19:21:28 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:28 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:28 InnoDB: Using Linux native AIO
121205 19:21:28 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:28 InnoDB: Completed initialization of buffer pool
121205 19:21:28 InnoDB: highest supported file format is Barracuda.
121205 19:21:28  InnoDB: Waiting for the background threads to start
121205 19:21:29 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 1597945
ERROR: 1050  Table 'plugin' already exists
121205 19:21:29 [ERROR] Aborting

121205 19:21:29 [Note] WSREP: Service disconnected.
121205 19:21:30 [Note] WSREP: Some threads may fail to exit.
121205 19:21:30  InnoDB: Starting shutdown...
121205 19:21:33  InnoDB: Shutdown completed; log sequence number 1597945
121205 19:21:33 [Note] /usr/sbin/mysqld: Shutdown complete

121205 19:21:34 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql/data
121205 19:21:34 mysqld_safe WSREP: Running position recovery with --log_error=/tmp/tmp.5Yq1viGeVb
121205 19:21:39 mysqld_safe WSREP: Failed to recover position: 
121205 19:21:39 [Note] WSREP: Read nil XID from storage engines, skipping position init
121205 19:21:39 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/libgalera_smm.so'
121205 19:21:39 [Note] WSREP: wsrep_load(): Galera 2.2(r137) by Codership Oy <info@codership.com> loaded succesfully.
121205 19:21:39 [Warning] WSREP: Could not open saved state file for reading: /var/lib/mysql/data//grastate.dat
121205 19:21:39 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
121205 19:21:39 [Note] WSREP: Preallocating 134219048/134219048 bytes in '/var/lib/mysql/data//galera.cache'...
121205 19:21:39 [Note] WSREP: Passing config to GCS: base_host = 10.0.2.15; base_port = 4567; cert.log_conflicts = no; gcache.dir = /var/lib/mysql/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1; 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; gcs.sync_donor = NO; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3
121205 19:21:39 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
121205 19:21:39 [Note] WSREP: wsrep_sst_grab()
121205 19:21:39 [Note] WSREP: Start replication
121205 19:21:39 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
121205 19:21:39 [Note] WSREP: protonet asio version 0
121205 19:21:39 [Note] WSREP: backend: asio
121205 19:21:39 [Note] WSREP: GMCast version 0
121205 19:21:39 [Note] WSREP: (e74c15bb-3f3a-11e2-0800-108a43f983cb, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
121205 19:21:39 [Note] WSREP: (e74c15bb-3f3a-11e2-0800-108a43f983cb, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
121205 19:21:39 [Note] WSREP: EVS version 0
121205 19:21:39 [Note] WSREP: PC version 0
121205 19:21:39 [Note] WSREP: gcomm: connecting to group 'database3.dfw2', peer ''
121205 19:21:39 [Note] WSREP: view(view_id(PRIM,e74c15bb-3f3a-11e2-0800-108a43f983cb,1) memb {
        e74c15bb-3f3a-11e2-0800-108a43f983cb,
} joined {
} left {
} partitioned {
})
121205 19:21:39 [Note] WSREP: gcomm: connected
121205 19:21:39 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
121205 19:21:39 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
121205 19:21:39 [Note] WSREP: Opened channel 'database3.dfw2'
121205 19:21:39 [Note] WSREP: Waiting for SST to complete.
121205 19:21:39 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
121205 19:21:39 [Note] WSREP: Starting new group from scratch: e74c62a6-3f3a-11e2-0800-b3d48a898a96
121205 19:21:39 [Note] WSREP: STATE_EXCHANGE: sent state UUID: e74c6dc5-3f3a-11e2-0800-918b8a40c68d
121205 19:21:39 [Note] WSREP: STATE EXCHANGE: sent state msg: e74c6dc5-3f3a-11e2-0800-918b8a40c68d
121205 19:21:39 [Note] WSREP: STATE EXCHANGE: got state msg: e74c6dc5-3f3a-11e2-0800-918b8a40c68d from 0 (server-4562.dfw2)
121205 19:21:39 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 0,
        members    = 1/1 (joined/total),
        act_id     = 0,
        last_appl. = -1,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = e74c62a6-3f3a-11e2-0800-b3d48a898a96
121205 19:21:39 [Note] WSREP: Flow-control interval: [16, 16]
121205 19:21:39 [Note] WSREP: Restored state OPEN -> JOINED (0)
121205 19:21:39 [Note] WSREP: New cluster view: global state: e74c62a6-3f3a-11e2-0800-b3d48a898a96:0, view# 1: Primary, number of nodes: 1, my index: 0, protocol version 2
121205 19:21:39 [Note] WSREP: SST complete, seqno: 0
121205 19:21:39 [Note] Plugin 'FEDERATED' is disabled.
121205 19:21:39 InnoDB: The InnoDB memory heap is disabled
121205 19:21:39 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121205 19:21:39 InnoDB: Compressed tables use zlib 1.2.3
121205 19:21:39 InnoDB: Using Linux native AIO
121205 19:21:39 [Note] WSREP: Member 0 (server-4562.dfw2) synced with group.
121205 19:21:39 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
121205 19:21:39 InnoDB: Initializing buffer pool, size = 128.0M
121205 19:21:39 InnoDB: Completed initialization of buffer pool
121205 19:21:39 InnoDB: highest supported file format is Barracuda.
121205 19:21:39  InnoDB: Waiting for the background threads to start
121205 19:21:40 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.1 started; log sequence number 1598129
121205 19:21:40 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
121205 19:21:40 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
121205 19:21:40 [Note] Server socket created on IP: '0.0.0.0'.
121205 19:21:40 [Note] Event Scheduler: Loaded 0 events
121205 19:21:40 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.28-55-log'  socket: '/var/lib/mysql/mysqld.sock'  port: 3306  Percona XtraDB Cluster (GPL), wsrep_23.7.r3821
121205 19:21:40 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
121205 19:21:40 [Note] WSREP: Assign initial position for certification: 0, protocol version: 2
121205 19:21:40 [Note] WSREP: Synchronized with group, ready for connections
121205 19:21:40 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

Revision history for this message

dannie (daniz) wrote on 2013-03-04:

I've always had this problem when upgrading percona xtradb.
The mysql startup seems to have a too short wait-time for the process to come back with the status that it's started and everything is ok.

I used to be able to start mysqld manually after the failed update, wait for it to sync, then run the updater again (as the startup time of mysqld would be shorter) and get a successful update. But now the database has grown to big thus the startup taking more time and the dpkg now fails every time.

I've tried raising the init.d/mysql timeout but it resulted in the error below:

changed ->
            # 6s was reported in #352070 to be too few when using ndbcluster
            for i in 1 2 3 4 5 6 7 8 9 10 11 12 13 14; do
                sleep 1
...

to
sleep 3

....
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: New cluster view: global state: 05d60806-54e8-11e2-0800-a393de22c9a7:8017907, view# 5: Primary, number of nodes: 1, my index: 0, protocol version 2
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: Assign initial position for certification: 8017907, protocol version: 2
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [ERROR] WSREP: async IST sender failed to serve tcp://10.41.172.66:4568: ist send failed: 1', asio error 'Connection reset by peer': 104 (Connection reset by peer)
Mar 4 17:02:56 localhost mysqld: #011 at galera/src/ist.cpp:send():744
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [Warning] WSREP: Protocol violation. JOIN message sender 0 (ams-db1) is not in state transfer (SYNCED). Message ignored.
Mar 4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: async IST sender served
Mar 4 17:02:56 dal-db1 rsyncd[16583]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(549) [Receiver=3.0.9]
Mar 4 17:03:01 localhost mysqld: 130304 17:03:01 [Note] WSREP: cleaning up f6d2a1ef-84e4-11e2-0800-550ee301495a (tcp://10.41.172.66:4567)

Mar 4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Mar 4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
Mar 4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)'
Mar 4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!

I've always had this problem when upgrading percona xtradb.
The mysql startup seems to have a too short wait-time for the process to come back with the status that it's started and everything is ok.

I've tried raising the init.d/mysql timeout but it resulted in the error below:

changed ->
            # 6s was reported in #352070 to be too few when using ndbcluster
            for i in 1 2 3 4 5 6 7 8 9 10 11 12 13 14; do
                sleep 1
...

to 
               sleep 3

....
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: New cluster view: global state: 05d60806-54e8-11e2-0800-a393de22c9a7:8017907, view# 5: Primary, number of nodes: 1, my index: 0, protocol version 2
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: Assign initial position for certification: 8017907, protocol version: 2
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [ERROR] WSREP: async IST sender failed to serve tcp://10.41.172.66:4568: ist send failed: 1', asio error 'Connection reset by peer': 104 (Connection reset by peer)
Mar  4 17:02:56 localhost mysqld: #011 at galera/src/ist.cpp:send():744
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [Warning] WSREP: Protocol violation. JOIN message sender 0 (ams-db1) is not in state transfer (SYNCED). Message ignored.
Mar  4 17:02:56 localhost mysqld: 130304 17:02:56 [Note] WSREP: async IST sender served
Mar  4 17:02:56 dal-db1 rsyncd[16583]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(549) [Receiver=3.0.9]
Mar  4 17:03:01 localhost mysqld: 130304 17:03:01 [Note] WSREP:  cleaning up f6d2a1ef-84e4-11e2-0800-550ee301495a (tcp://10.41.172.66:4567)

Mar  4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Mar  4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
Mar  4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (111)'
Mar  4 17:03:29 dal-db1 /etc/init.d/mysql[17004]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!

Revision history for this message

dannie (daniz) wrote on 2013-03-07:

Any chance to get a look at this? Currently running with 1 node only cause of this.
Thanks

Changed in percona-xtradb-cluster:
status:	New → Incomplete

Raghavendra D Prabhu (raghavendra-prabhu) on 2013-04-04

Changed in percona-xtradb-cluster:
status:	Incomplete → New

Revision history for this message

Raghavendra D Prabhu (raghavendra-prabhu) wrote on 2013-04-12:

@Jervin

The issue you describe seems to be related to https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1104720

@daniz,

Can you confirm if your issue is https://bugs.launchpad.net/bugs/1099428

Revision history for this message

Raghavendra D Prabhu (raghavendra-prabhu) wrote on 2013-04-17:

Marking this as invalid for now based on #5. Please reopen this if required.

Changed in percona-xtradb-cluster:
status:	New → Invalid

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-18:

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1244

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.