search

ClusterLabs / resource-agents

Combined repository of OCF agents from the RHCS and Linux-HA projects
GNU General Public License v2.0
493 stars 580 forks source link

Galera: Unable to detect last known write sequence number #940

Open Leo-need opened 7 years ago

Leo-need commented 7 years ago

Our setup:

Pacemaker cluster: pacemaker-cluster-libs-1.1.15-11.el7_3.2.x86_64 pacemaker-libs-1.1.15-11.el7_3.2.x86_64 pacemaker-cli-1.1.15-11.el7_3.2.x86_64 pacemaker-1.1.15-11.el7_3.2.x86_64

4x nodes galera-cluster: MariaDB-server-10.1.21-1.el7.centos.x86_64 MariaDB-common-10.1.21-1.el7.centos.x86_64 MariaDB-client-10.1.21-1.el7.centos.x86_64 MariaDB-shared-10.1.21-1.el7.centos.x86_64 MariaDB-devel-10.1.21-1.el7.centos.x86_64 galera-25.3.19-1.rhel7.el7.centos.x86_64

And last lime we use follow resource agent:

In most cases after reboot all nodes in cluster we have:

This error replyes from 1 to 4 nodes.

So we can see logs from pacemaker and mariadb, and it looks like pacemaker can't send wsrep_cluster_address to mysql when it starts. This error repeats for SST methods - rsync and xtrabackup-v2

170306 12:32:38 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 170306 12:32:38 mysqld_safe WSREP: Running position recovery with —log_error='/var/lib/mysql/wsrep_recovery.V5Cuta' —pid-file='/var/lib/mysql/node03-recover.pid' 2017-03-06 12:32:38 140267724499200 [Note] /usr/sbin/mysqld (mysqld 10.1.21-MariaDB) starting as process 61644 ... 2017-03-06 12:32:38 140267724499200 [ERROR] WSREP: xtrabackup-v2 SST method requires wsrep_cluster_address to be configured on startup. 170306 12:32:41 mysqld_safe WSREP: Position recovery skipped 2017-03-06 12:32:41 140431155935488 [Warning] You need to use —log-bin to make —binlog-format work. 2017-03-06 12:32:41 140431155935488 [Note] /usr/sbin/mysqld (mysqld 10.1.21-MariaDB) starting as process 61735 ... 2017-03-06 12:32:41 140431155935488 [ERROR] WSREP: xtrabackup-v2 SST method requires wsrep_cluster_address to be configured on startup. 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: The InnoDB memory heap is disabled 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Compressed tables use zlib 1.2.7 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Using Linux native AIO 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Using SSE crc32 instructions 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Initializing buffer pool, size = 128.0M 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Completed initialization of buffer pool 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Highest supported file format is Barracuda. 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: 128 rollback segment(s) are active. 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Waiting for purge to start 2017-03-06 12:32:41 140431155935488 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 2458757979 2017-03-06 12:32:41 140431155935488 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery. 2017-03-06 12:32:41 140431155935488 [Note] Plugin 'FEEDBACK' is disabled. 2017-03-06 12:32:41 140431155935488 [Note] Server socket created on IP: '0.0.0.0'. 2017-03-06 12:32:41 140431155935488 [Note] WSREP: disabled, skipping position recovery 170306 12:32:44 mysqld_safe mysqld from pid file /var/run/mysql/mysqld.pid ended

psyelephant commented 7 years ago

I have same situation with CentOS 7.2 MariaDB 10.1.21 Please provide any info about versions of packages which work together correctly.

dciabrin commented 7 years ago

@Leo-need , as per https://github.com/ClusterLabs/resource-agents/pull/938, mariadb 10.1.21 changed the way it logs the wsrep sequence number, did you test the latest version of the agent from last week?

Leo-need commented 7 years ago

yes. i test this version https://github.com/ClusterLabs/resource-agents/blob/master/heartbeat/galera

dciabrin commented 7 years ago

So i've just installed packages you mentionned from MariaDB:

MariaDB-common-10.1.21-1.el7.centos.x86_64 MariaDB-client-10.1.21-1.el7.centos.x86_64 galera-25.3.19-1.rhel7.el7.centos.x86_64 MariaDB-shared-10.1.21-1.el7.centos.x86_64 MariaDB-server-10.1.21-1.el7.centos.x86_64

on a CentOS Linux release 7.2.1511 (Core)

I can see the cluster bootstrap correctly, and each node can individually be restarted without issue.

However, if the entire cluster is stopped and re-bootstrapped, you will hit https://github.com/ClusterLabs/resource-agents/issues/915. There's a workaround proposed in the issue, but I'd like to come up with a solution which could reconcile the current strategy and the new hint before merging.

If you can't use the workaround above, the resource agent is known to work with mariadb/galera 10.1.20. There are CentOS packages built by the RDO project:

# install the .repo which provide mariadb community version
yum install -y centos-release-openstack-mitaka
# install mariadb and galera
yum install mariadb mariadb-server galera
psyelephant commented 7 years ago

@dciabrin Thank you for test and advise! I'll try mariadb from RDO project and will provide you feedback. Thank you a lot!

Leo-need commented 7 years ago

@dciabrin Hello! We tried to install older versions of maria packages: MariaDB-shared-10.0.27-1.el7.centos.x86_64 MariaDB-common-10.0.27-1.el7.centos.x86_64 MariaDB-client-10.0.27-1.el7.centos.x86_64 MariaDB-Galera-server-10.0.27-1.el7.centos.x86_64 MariaDB-devel-10.0.27-1.el7.centos.x86_64 galera-25.3.17-1.rhel7.el7.centos.x86_64

And everythink looks better, but in one of reboot attempts we got follow error:

70307 17:12:22 mysqld_safe WSREP: Recovered position 0490d94e-031d-11e7-bb55-9211159dbf50:30355 170307 17:12:22 [Note] /usr/sbin/mysqld (mysqld 10.0.27-MariaDB-wsrep) starting as process 14132 ... 170307 17:12:22 [Note] WSREP: Read nil XID from storage engines, skipping position init 170307 17:12:22 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so' 170307 17:12:22 [Note] WSREP: wsrep_load(): Galera 25.3.17(r3619) by Codership Oy info@codership.com loaded successfully. 170307 17:12:22 [Note] WSREP: CRC-32C: using hardware acceleration. 170307 17:12:22 [Note] WSREP: Found saved state: 0490d94e-031d-11e7-bb55-9211159dbf50:-1 170307 17:12:22 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 172.28.50.23; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; 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; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; 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; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; 170307 17:12:22 [Note] WSREP: Service thread queue flushed. 170307 17:12:22 [Note] WSREP: Assign initial position for certification: 30355, protocol version: -1 170307 17:12:22 [Note] WSREP: wsrep_sst_grab() 170307 17:12:22 [Note] WSREP: Start replication 170307 17:12:22 [Note] WSREP: Setting initial position to 0490d94e-031d-11e7-bb55-9211159dbf50:30355 170307 17:12:22 [Note] WSREP: protonet asio version 0 170307 17:12:22 [Note] WSREP: Using CRC-32C for message checksums. 170307 17:12:22 [Note] WSREP: backend: asio 170307 17:12:22 [Note] WSREP: gcomm thread scheduling priority set to other:0 170307 17:12:22 [Note] WSREP: restore pc from disk successfully 170307 17:12:22 [Note] WSREP: GMCast version 0 170307 17:12:22 [Note] WSREP: (00000000, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567 170307 17:12:22 [Note] WSREP: (00000000, 'tcp://0.0.0.0:4567') multicast: , ttl: 1 170307 17:12:22 [ERROR] WSREP: failed to open gcomm backend connection: 131: invalid UUID: 00000000 (FATAL) at gcomm/src/pc.cpp:PC():271 170307 17:12:22 [ERROR] WSREP: gcs/src/gcs_core.cpp:gcs_core_open():208: Failed to open backend connection: -131 (State not recoverable) 170307 17:12:22 [ERROR] WSREP: gcs/src/gcs.cpp:gcs_open():1380: Failed to open channel 'galera_one' at 'gcomm://node01,node02,node03,node04': -131 (State not recoverable) 170307 17:12:22 [ERROR] WSREP: gcs connect failed: State not recoverable 170307 17:12:22 [ERROR] WSREP: wsrep::connect(gcomm://node01,node02,node03,node04) failed: 7 170307 17:12:22 [ERROR] Aborting 170307 17:12:22 [Note] WSREP: Service disconnected. 170307 17:12:23 [Note] WSREP: Some threads may fail to exit. 170307 17:12:23 [Note] /usr/sbin/mysqld: Shutdown complete

So we can solve it by delete /var/lib/mysql/gvwstate.dat and reenabling resource. It can work but we want to automate it. How we can change resource agent for solve it? Or maybe you can show us our mistakes in installation?

Also we use updated resource agent from centos distrib: resource-agents-3.9.5-82.el7_3.6.x86_64 with added:

local tmp=$(mktemp) chown $OCF_RESKEY_user:$OCF_RESKEY_group $tmp

dciabrin commented 7 years ago

@Leo-need gvwstate.dat is only maintained by galera and should contain valid UUID (e.g. 2881bf89-02b1-11e7-83d6-029aaecb876a) If galera retrieves invalid UUID from this file (e.g. 00000000), you're problaby hitting https://github.com/codership/galera/issues/354.

It all depends on how you "restarted" galera on the node: . did you ask pacemaker to stop galera on the node, and restart it? . did you kill the galera pid and let pacemaker restart it? . did you powercycle the host on which galera was running? . is the host a VM, and if so how is the disk cache configured?

Without more logs, it sounds like a hardware/VM setup issue, and trying to overcome that from the resource agent is probably asking for trouble.

Leo-need commented 7 years ago

@dciabrin we have hardware installation, and make some stress-test on it. so we got this error only in case of hard reboot at the same time all 4 hosts in cluster.

dciabrin commented 7 years ago

@Leo-need hmm that's weird. is it possible to share /var/log/mysqld.log of all the nodesm as well as the contents of gvwstate.dat, so that I try to reproduce locally? If we have a good reproducer, I think we should update codership/galera#354

Leo-need commented 7 years ago

@dciabrin we got this error only once and only on 2 hosts (node03, node04). logs in attachments unfortunately I can't reproduce the contents of gvwstate.dat now this files contains:

node01 my_uuid: 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824

vwbeg

view_id: 3 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 10 bootstrap: 0 member: 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 0 member: 8f0f6046-04c2-11e7-8853-3a870df5cd0f 0 member: c5826260-04c2-11e7-b7d4-5a5995b6eed1 0 member: cbd452bc-04c2-11e7-84a6-83a116617200 0

vwend

node02 my_uuid: cbd452bc-04c2-11e7-84a6-83a116617200

vwbeg

view_id: 3 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 10 bootstrap: 0 member: 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 0 member: 8f0f6046-04c2-11e7-8853-3a870df5cd0f 0 member: c5826260-04c2-11e7-b7d4-5a5995b6eed1 0 member: cbd452bc-04c2-11e7-84a6-83a116617200 0

vwend

node03 my_uuid: 8f0f6046-04c2-11e7-8853-3a870df5cd0f

vwbeg

view_id: 3 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 10 bootstrap: 0 member: 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 0 member: 8f0f6046-04c2-11e7-8853-3a870df5cd0f 0 member: c5826260-04c2-11e7-b7d4-5a5995b6eed1 0 member: cbd452bc-04c2-11e7-84a6-83a116617200 0

vwend

node04 my_uuid: c5826260-04c2-11e7-b7d4-5a5995b6eed1

vwbeg

view_id: 3 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 10 bootstrap: 0 member: 38b42ff8-04ca-11e7-ba1d-8e6eef8e8824 0 member: 8f0f6046-04c2-11e7-8853-3a870df5cd0f 0 member: c5826260-04c2-11e7-b7d4-5a5995b6eed1 0 member: cbd452bc-04c2-11e7-84a6-83a116617200 0

vwend

mysqld_node01.txt mysqld_node02.txt mysqld_node03.txt mysqld_node04.txt

Leo-need commented 7 years ago

@dciabrin

Hello ! We still test our installation on a different hardware. Sometimes we see problems, which we can fix by guide from this topic: https://github.com/codership/galera/issues/354 Mysql's log contain lines which repeatedly repeats:

170424 17:04:42 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
170424 17:04:42 mysqld_safe WSREP: Running position recovery with --log_error='/var/lib/mysql/wsrep_recovery.0AOur0' --pid-file='/var/lib/mysql/node01-recover.pid'
170424 17:04:42 [Note] /usr/sbin/mysqld (mysqld 10.0.27-MariaDB-wsrep) starting as process 184353 ...
170424 17:04:44 mysqld_safe WSREP: Recovered position 9cf3c99e-20ef-11e7-b232-faac4becfe8b:152994
170424 17:04:44 [Note] /usr/sbin/mysqld (mysqld 10.0.27-MariaDB-wsrep) starting as process 184403 ...
170424 17:04:44 [Note] InnoDB: Using mutexes to ref count buffer pool pages
170424 17:04:44 [Note] InnoDB: The InnoDB memory heap is disabled
170424 17:04:44 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
170424 17:04:44 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
170424 17:04:44 [Note] InnoDB: Compressed tables use zlib 1.2.7
170424 17:04:44 [Note] InnoDB: Using Linux native AIO
170424 17:04:44 [Note] InnoDB: Using CPU crc32 instructions
170424 17:04:44 [Note] InnoDB: Initializing buffer pool, size = 128.0M
170424 17:04:44 [Note] InnoDB: Completed initialization of buffer pool
170424 17:04:44 [Note] InnoDB: Highest supported file format is Barracuda.
170424 17:04:44 [Note] InnoDB: 128 rollback segment(s) are active.
170424 17:04:44 [Note] InnoDB: Waiting for purge to start
170424 17:04:44 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.31-77.0 started; log sequence number 385602845
170424 17:04:44 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery.
170424 17:04:44 [Note] Plugin 'FEEDBACK' is disabled.
170424 17:04:44 [Note] Server socket created on IP: '0.0.0.0'.
170424 17:04:44 [Note] WSREP: Recovered position: 9cf3c99e-20ef-11e7-b232-faac4becfe8b:152994
170424 17:04:44 [Note] InnoDB: FTS optimize thread exiting.
170424 17:04:44 [Note] InnoDB: Starting shutdown...
170424 17:04:47 [Note] InnoDB: Shutdown completed; log sequence number 385602855
170424 17:04:47 [Note] /usr/sbin/mysqld: Shutdown complete

On Pacemaker side a only one problem:

Apr 24 17:05:01 node01 galera(galera)[181914]: ERROR: MySQL server failed to start (pid=182328) (rc=0), please check your installation
Apr 24 17:05:01 node01 lrmd[4390]:  notice: galera_promote_0:181914:stderr [ ocf-exit-reason:MySQL server failed to start (pid=182328) (rc=0), please check your installation ]
Apr 24 17:05:01 node01 crmd[4393]:  notice: Result of promote operation for galera on node01: 1 (unknown error)
Apr 24 17:05:01 node01 crmd[4393]:  notice: node01-galera_promote_0:135 [ ocf-exit-reason:MySQL server failed to start (pid=182328) (rc=0), please check your installation\n ]

May you provide us some advice about good way to achieve a automatic fixing? We use patched agent. Please check it:

galera_ra.txt

svenvogel commented 7 years ago

Hi,

we have the same problem. I use CentOS Linux release 7.3.1611 (Core).

Packages: pacemaker.x86_641. 1.15-11.el7_3.5
pacemaker-cli.x86_64 1.1.15-11.el7_3.5 pacemaker-cluster-libs.x86_64 1.1.15-11.el7_3.5
pacemaker-libs.x86_64 1.1.15-11.el7_3.5

percona-xtrabackup-24.x86_64 2.4.7-2.el7

MariaDB-server.x86_64 10.2.6-1.el7.centos

we had the same problem with the "Unable to detect last known write sequence number". we setup the cluster always manually and all things works fine, when pacemaker was in maintenance mode. after that we go outside maintenance and cluster starts with "... sequence number ..." error. i tried all version.

i read both issues #940 and #915

i used the file from #915 from the openstack community like @dciabrin wrote it. https://raw.githubusercontent.com/DoclerLabs/openstack/master/openstack-installer/roles/galera/files/galera-agent

at the moment i dont have the problem. reboot of a node works and they come back online to the cluster without a problem.

sed -i 's/^safe_to_bootstrap:.*/safe_to_bootstrap: 1/' ${OCF_RESKEY_datadir}/grastate.dat seems to workaround the problem for the moment. i dont know if that the right fix for that, but at the moment it seems to work.

@dciabrin what do you think whats the main problem?

greets

Sven

dciabrin commented 6 years ago

@Leo-need FWIW I just proposed #1052 to overcome the issue of empty gvwstate.dat.

gyurco commented 6 years ago

I've also met a problem which Leo-need's log above demonstates: starting mysqld_safe changes the --log-error to something in /var/lib/mysql/wsrep_recovery.xxx, so the RA cannot detect the last sequence number. So as a workaround I'm configuring 'binary' to /usr/sbin/mysqld now.

170424 17:04:42 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
170424 17:04:42 mysqld_safe WSREP: Running position recovery with --log_error='/var/lib/mysql/wsrep_recovery.0AOur0' --pid-file='/var/lib/mysql/node01-recover.pid
dciabrin commented 6 years ago

Hey gyurco, ok this thread is starting to accumulate too many different bugs that yield a similar symptom (not being able to detect seqno).I'm in favor of closing this issue now because it seemed to be caused by gvwstate.dat being empty. That being said, there might be a specific condition that the PR above did not fix yet.

Have you tried the latest version of the resource agent to see if that fixes your problem? If not, would you mind opening a dedicated issue and provide details about rpm version you use, which operation the resource agent is not able to perform (start, monitor, stop) and potential logs associate with the failure?

PS: I think mysqld_safe should not be changed for mysqld, as it performs some useful startup checks and whatnot.

gyurco commented 6 years ago

Hi @dciabrin,

Yes, I've tried the latest, but the fact is that mysqld_safe changes --log-error anyway (it does not really depend on the RA). It started with the last couple of Percona releases, now I'm using percona-xtradb-cluster-server-5.7 - 5.7.19-29.22-3.xenial (deb). I'll try to examine if it is the desired behavior (and why).

Here's a new issue with some logs: https://github.com/ClusterLabs/resource-agents/issues/1094