1499796 – Concurrent 'pcs resource disable ...' doesn't always disable all mentioned resources.

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1499796 - Concurrent 'pcs resource disable ...' doesn't always disable all mentioned resources.

Summary: Concurrent 'pcs resource disable ...' doesn't always disable all mentioned re...

Keywords:
Status:	CLOSED DUPLICATE of bug 1441673
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	pcs
Sub Component:
Version:	7.4
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	Tomas Jelinek
QA Contact:	cluster-qe@redhat.com
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-10-09 12:13 UTC by Ondrej Faměra
Modified:	2021-06-10 13:13 UTC (History)
CC List:	5 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-10-12 08:56:23 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
corosync.log from reproducer (24.48 KB, text/plain) 2017-10-09 12:13 UTC, Ondrej Faměra	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Knowledge Base (Solution)	3456901	0	None	None	None	2018-05-23 12:13:18 UTC

Description Ondrej Faměra 2017-10-09 12:13:43 UTC

Created attachment 1336378 [details]
corosync.log from reproducer

=== Description of problem:
Running 'pcs resource disable' on 2 nodes or in 2 instances at _same_ time causes the one of the commands to be not honoured. Both commands will exit with exit code 0.

=== Version-Release number of selected component (if applicable):
pcs-0.9.158-6.el7

=== How reproducible:
Need to achieve concurrent run of 'pcs resource disable' commands either on one node or multiple nodes within 1 second (or less).

=== How to reproduce:
Several ways on how to reproduce - CRON with commands at same time or with Ansible playbook as shown below.

1. create hosts file and playbook
# hosts
[cluster]
192.168.11.183 res1=test_1
192.168.11.184 res1=test_2

# disable_resources.yml
---  
- hosts: cluster  
  remote_user: root  
  tasks:  
  - name: disable resource set 1
    command: "pcs resource disable {{ res1 }}"

2. Run the playbook and observe what will happen when 2 nodes at same time will attempt to 'disable' a different resources.
# ansible-playbook -i hosts disable_resources.yml
...
  changed: [192.168.11.183] => {"changed": true, "cmd": ["pcs", "resource", "disable", "test_1"], "delta": "0:00:00.142540", "end": "2017-10-05 15:56:35.588529", "rc": 0, "start": "2017-10-05 15:56:35.445989", "stderr": "", "stdout": "", "stdout_lines": [], "warnings": []}
  changed: [192.168.11.184] => {"changed": true, "cmd": ["pcs", "resource", "disable", "test_2"], "delta": "0:00:00.159837", "end": "2017-10-05 15:56:35.606808", "rc": 0, "start": "2017-10-05 15:56:35.446971", "stderr": "", "stdout": "", "stdout_lines": [], "warnings": []}
...

=== Expected result:
  Resources 'test_1' and 'test_2' will be disabled after the ansible playbook run.

=== Actual result:
  Only one resource is disabled.


=== Additional information:
  Using 'pcs resource disable ...' naming all resources to be disabled is current workaround in case of one node.
  If 2 nodes needs to execute 'pcs resource disable' at same time (via cron) we need to introduce the delay (sleep)
  on one of the nodes to avoid the situation.

Below are relevant logs from above test with comments

pcs status (before)
 test_1	(ocf::pacemaker:Dummy):	Started fastvm-rhel-7-4-183
 test_2	(ocf::pacemaker:Dummy):	Started fastvm-rhel-7-4-184

Oct 05 15:56:34 [13046] fastvm-rhel-7-4-183        cib:     info: cib_process_ping:	Reporting our current digest to fastvm-rhel-7-4-184: 8c974c6c1dc80ec1ef989043c300aeed for 0.35.74 (0x5631e8681d20 0)
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_process_request:	Forwarding cib_replace operation for section configuration to all (origin=local/cibadmin/2)
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: --- 0.35.74 2
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: +++ 0.36.0 (null)
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	+  /cib:  @epoch=36, @num_updates=0
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++ /cib/configuration/resources/primitive[@id='test_1']:  <meta_attributes id="test_1-meta_attributes"/>
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++                                                          <nvpair id="test_1-meta_attributes-target-role" name="target-role" value="Stopped"/>
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++                                                        </meta_attributes>
## ^^ here we seem to add lines defining the resource 'test_1' to be in disabled state (target-role: Stopped)

Oct 05 15:56:35 [13048] fastvm-rhel-7-4-183       lrmd:     info: cancel_recurring_action:	Cancelling ocf operation test_1_monitor_10000
Oct 05 15:56:35 [13051] fastvm-rhel-7-4-183       crmd:     info: do_lrm_rsc_op:	Performing key=36:74:0:0d6ef819-c59a-430c-9999-60c999364659 op=test_1_stop_0
Oct 05 15:56:35 [13048] fastvm-rhel-7-4-183       lrmd:     info: log_execute:	executing - rsc:test_1 action:stop call_id:343
## ^^ here we can see that cluster is actually stopping the resource to reach the disabled state

Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: --- 0.36.0 2
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: +++ 0.37.0 (null)
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	-- /cib/configuration/resources/primitive[@id='test_1']/meta_attributes[@id='test_1-meta_attributes']
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	+  /cib:  @epoch=37
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++ /cib/configuration/resources/primitive[@id='test_2']:  <meta_attributes id="test_2-meta_attributes"/>
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++                                                          <nvpair id="test_2-meta_attributes-target-role" name="target-role" value="Stopped"/>
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	++                                                        </meta_attributes>
## ^^ here we see a second request where the 'test_2' resource should be put into disabled state (target-role: Stopped). Here we also see that we will be replacing line in cib XML with "primitive[@id='test_1']/meta_attributes[@id='test_1-meta_attributes']".
However in that part of CIB XML we have also the definition that 'test_1' should be disabled.

Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: --- 0.37.0 2
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	Diff: +++ 0.37.1 (null)
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	+  /cib:  @num_updates=1
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:	+  /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='test_1']/lrm_rsc_op[@id='test_1_last_0']:  @operation_key=test_1_stop_0, @operation=stop, @transition-key=36:74:0:0d6ef819-c59a-430c-9999-60c999364659, @transition-magic=0:0;36:74:0:0d6ef819-c59a-430c-9999-60c999364659, @call-id=343, @last-run=1507211795, @last-rc-change=1507211795, @exec-time=17
Oct 05 15:56:35 [13046] fastvm-rhel-7-4-183        cib:     info: cib_process_request:	Completed cib_modify operation for section status: OK (rc=0, origin=fastvm-rhel-7-4-183/crmd/221, version=0.37.1)
Oct 05 15:56:35 [13051] fastvm-rhel-7-4-183       crmd:     info: do_lrm_rsc_op:	Performing key=36:75:0:0d6ef819-c59a-430c-9999-60c999364659 op=test_1_start_0
Oct 05 15:56:35 [13048] fastvm-rhel-7-4-183       lrmd:     info: log_execute:	executing - rsc:test_1 action:start call_id:346
## ^^ as the test_1 is not in disabled state, the cluster will attempt to start it.

pcs status (after)
 test_1	(ocf::pacemaker:Dummy):	Started fastvm-rhel-7-4-183
 test_2	(ocf::pacemaker:Dummy):	Stopped (disabled)

Comment 3 Tomas Jelinek 2017-10-09 12:51:49 UTC

I believe this is already fixed by bz1441673.

The fix only applies to pcs commands overhauled to the new architecture. However, "pcs resource disable" and "pcs resource enable" have been overhauled in https://github.com/ClusterLabs/pcs/commit/0c4cba8bdb69c8984cd84a0769c35dc52cdc5be6 which has been included in pcs 0.9.157 and never.

Note that using commands which are not yet overhauled may still trigger the described race condition.

Possible workaround is to edit the CIB in a file and push a diff of changes to the cluster. This feature has been implemented and described in bz1404233.

Comment 7 Ondrej Faměra 2017-10-12 07:49:01 UTC

Tested with test package from bz1441673 on my setup and it now behaves correctly.
Should we mark this as duplicate of bz1441673?

I have tested both 'pcs resource enable' and 'pcs resource disable'.

Also from logs it looks more the way I would expect it ('pcs resource disable' log below)

Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        Diff: --- 0.41.7 2
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        Diff: +++ 0.42.0 (null)
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        +  /cib:  @epoch=42, @num_updates=0
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++ /cib/configuration/resources/primitive[@id='test_2']:  <meta_attributes id="test_2-meta_attributes"/>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++                                                          <nvpair id="test_2-meta_attributes-target-role" name="target-role" value="Stopped"/>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++                                                        </meta_attributes>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_process_request:   Completed cib_apply_diff operation for section 'all': OK (rc=0, origin=fastvm-rhel-7-4-184/cibadmin/2, version=0.42.0)

Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        Diff: --- 0.42.0 2
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        Diff: +++ 0.43.0 (null)
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        +  /cib:  @epoch=43
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++ /cib/configuration/resources/primitive[@id='test_1']:  <meta_attributes id="test_1-meta_attributes"/>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++                                                          <nvpair id="test_1-meta_attributes-target-role" name="target-role" value="Stopped"/>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_perform_op:        ++                                                        </meta_attributes>
Oct 12 09:29:03 [1228] fastvm-rhel-7-4-183        cib:     info: cib_process_request:   Completed cib_apply_diff operation for section 'all': OK (rc=0, origin=fastvm-rhel-7-4-183/cibadmin/2, version=0.43.0)

Comment 8 Tomas Jelinek 2017-10-12 08:56:23 UTC

Closing as proposed in comment 7.

*** This bug has been marked as a duplicate of bug 1441673 ***

Note You need to log in before you can comment on or make changes to this bug.