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 2095597 - A duplicate ACL user causes a DC election loop (RHEL 7)
Summary: A duplicate ACL user causes a DC election loop (RHEL 7)
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: pacemaker
Version: 7.9
Hardware: All
OS: Linux
low
high
Target Milestone: rc
: ---
Assignee: Ken Gaillot
QA Contact: cluster-qe@redhat.com
URL:
Whiteboard:
Depends On:
Blocks: 2095662
TreeView+ depends on / blocked
 
Reported: 2022-06-10 00:48 UTC by Reid Wahl
Modified: 2022-10-06 20:37 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 2095662 (view as bug list)
Environment:
Last Closed: 2022-10-06 20:37:42 UTC
Target Upstream Version:
Embargoed:
pm-rhel: mirror+

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker KCSOPP-1920 0 None None None 2022-06-10 00:49:38 UTC
Red Hat Issue Tracker RHELPLAN-124939 0 None None None 2022-06-10 00:59:49 UTC
Red Hat Knowledge Base (Solution) 6972522 0 None None None 2022-08-18 17:10:24 UTC

Description Reid Wahl 2022-06-10 00:48:26 UTC 
Description of problem:

If a duplicate ACL user (acl_target) exists in the CIB, DC elections will loop quickly and infinitely. There is no good reason to have a duplicate ACL user, but pacemaker should not fail in this way if a user makes this mistake.

    <acls>
      <acl_role id="read-access">
        <acl_permission id="read-access-read" kind="read" xpath="/"/>
      </acl_role>
      <acl_target id="testuser">
        <role id="read-access"/>
      </acl_target>
      <acl_target id="testuser">
        <role id="read-access"/>
      </acl_target>
    </acls>

[root@fastvm-rhel-7-6-21 pcs]# tail -f /var/log/messages
Jun  9 17:31:25 fastvm-rhel-7-6-21 crmd[17198]:  notice: State transition S_ELECTION -> S_INTEGRATION
Jun  9 17:31:25 fastvm-rhel-7-6-21 stonith-ng[17194]:  notice: Versions did not change in patch 0.40.3
Jun  9 17:31:25 fastvm-rhel-7-6-21 attrd[17196]:  notice: Updating all attributes after cib_refresh_notify event
Jun  9 17:31:25 fastvm-rhel-7-6-21 crmd[17198]:  notice: State transition S_ELECTION -> S_INTEGRATION
Jun  9 17:31:25 fastvm-rhel-7-6-21 stonith-ng[17194]:  notice: Versions did not change in patch 0.40.7
Jun  9 17:31:25 fastvm-rhel-7-6-21 attrd[17196]:  notice: Updating all attributes after cib_refresh_notify event

Detailed logs are in "Additional info."

Note: I have not tested on RHEL 8 yet; not sure if the issue is present there.

Also note: pcs does not allow this duplicate creation.

[root@fastvm-rhel-7-6-21 pcs]# pcs acl user create testuser read-access
Error: 'testuser' already exists

But if the duplicate already exists, pcs seems unable to remove it. It has to be removed manually and then pushed. IMO this isn't worth fixing in pcs, but others' opinions may differ.

-----

Version-Release number of selected component (if applicable):

pacemaker-1.1.23-1.el7_9.1

-----

How reproducible:

Always

-----

Steps to Reproduce:
1. Enable ACLs (`pcs acl enable`).
2. Save the CIB to a file (`pcs cluster cib > /tmp/cib.xml`), and add the following to /tmp/cib.xml, just before the closing </configuration> tag.

    <acls>
      <acl_role id="read-access">
        <acl_permission id="read-access-read" kind="read" xpath="/"/>
      </acl_role>
      <acl_target id="testuser">
        <role id="read-access"/>
      </acl_target>
      <acl_target id="testuser">
        <role id="read-access"/>
      </acl_target>
    </acls>

3. Push the updated CIB (`pcs cluster cib-push --config /tmp/cib.xml`).
4. It may be necessary to perform a full cluster stop-and-start in order to produce the issue.

-----

Actual results:

An infinite and rapid DC election loop as shown in the description.

-----

Expected results:

No DC election loop; perhaps a warning or failure due to the duplicate ACL user, or perhaps ignore the duplicate.

-----

Additional info:

Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (     utils.c:975   )    info: update_dc:        Set DC to node1 (3.0.14)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section crm_config: OK (rc=0, origin=node1/crmd/574, version=0.40.125)
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (       fsa.c:548   )    info: do_state_transition:      State transition S_INTEGRATION -> S_FINALIZE_JOIN | input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (   cib_ops.c:230   )    info: cib_process_replace:      Digest matched on replace from node1: a0c66419385d0b14385cfa03f3e8d523
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (   cib_ops.c:266   )    info: cib_process_replace:      Replaced 0.40.125 with 0.40.125 from node1
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:3531  )    info: __xml_diff_object:        acl_target.testuser moved from 1 to 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:891   )    info: cib_perform_op:   cib_perform_op: Local-only Change: 0.40.125
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:920   )    info: cib_perform_op:   +~ /cib/configuration/acls/acl_target[@id='testuser'] moved to offset 2
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (       cib.c:316   )    info: controld_delete_node_state:       Deleting resource history for node node1 (via CIB call 580) | xpath=//node_state[@uname='node1']/lrm
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (       cib.c:316   )    info: controld_delete_node_state:       Deleting resource history for node node2 (via CIB call 582) | xpath=//node_state[@uname='node2']/lrm
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (    notify.c:366   )    info: cib_replace_notify:       Local-only Replace: 0.40.125 from node1
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_replace operation for section 'all': OK (rc=0, origin=node1/crmd/577, version=0.40.125)
Jun 09 17:31:25 [17196] fastvm-rhel-7-6-21      attrd: (      main.c:97    )  notice: attrd_cib_replaced_cb:    Updating all attributes after cib_refresh_notify event
Jun 09 17:31:25 [17196] fastvm-rhel-7-6-21      attrd: (  commands.c:1079  )   debug: write_attributes: Writing out all attributes
Jun 09 17:31:25 [17196] fastvm-rhel-7-6-21      attrd: (  commands.c:1290  )    info: write_attribute:  Processed 2 private changes for #attrd-protocol, id=n/a, set=n/a
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1320  )  notice: xml_patch_version_check:  Versions did not change in patch 0.40.125
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (       fsa.c:548   )    info: do_state_transition:      State transition S_FINALIZE_JOIN -> S_ELECTION | input=I_ELECTION cause=C_FSA_INTERNAL origin=do_cib_replaced
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (     utils.c:979   )    info: update_dc:        Unset DC. Was node1
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section nodes to all (origin=local/crmd/578)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section nodes to all (origin=local/crmd/579)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_delete operation for section //node_state[@uname='node1']/lrm to all (origin=local/crmd/580)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section status to all (origin=local/crmd/581)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_delete operation for section //node_state[@uname='node2']/lrm to all (origin=local/crmd/582)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (  cib_file.c:293   )    info: cib_file_backup:  Archived previous version as /var/lib/pacemaker/cib/cib-82.raw
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (  election.c:381   )    info: election_check:   election-DC won by local node
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (      misc.c:46    )    info: do_log:   Input I_ELECTION_DC received in state S_ELECTION from election_win_cb
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section nodes: OK (rc=0, origin=node1/crmd/578, version=0.40.125)
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (       fsa.c:548   )  notice: do_state_transition:      State transition S_ELECTION -> S_INTEGRATION | input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=election_win_cb
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section nodes: OK (rc=0, origin=node1/crmd/579, version=0.40.125)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:884   )    info: cib_perform_op:   Diff: --- 0.40.125 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:886   )    info: cib_perform_op:   Diff: +++ 0.40.126 (null)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:966   )    info: cib_perform_op:   -- /cib/status/node_state[@id='1']/lrm[@id='1']
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib:  @num_updates=126
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_delete operation for section //node_state[@uname='node1']/lrm: OK (rc=0, origin=node1/crmd/580, version=0.40.126)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:884   )    info: cib_perform_op:   Diff: --- 0.40.126 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:886   )    info: cib_perform_op:   Diff: +++ 0.40.127 (null)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib:  @num_updates=127
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib/status/node_state[@id='1']:  @crm-debug-origin=do_lrm_query_internal
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:908   )    info: cib_perform_op:   ++ /cib/status/node_state[@id='1']:  <lrm id="1"/>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:915   )    info: cib_perform_op:   ++                                     <lrm_resources/>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:915   )    info: cib_perform_op:   ++                                   </lrm>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section status: OK (rc=0, origin=node1/crmd/581, version=0.40.127)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:884   )    info: cib_perform_op:   Diff: --- 0.40.127 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:886   )    info: cib_perform_op:   Diff: +++ 0.40.128 (null)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:966   )    info: cib_perform_op:   -- /cib/status/node_state[@id='2']/lrm[@id='2']
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib:  @num_updates=128
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_delete operation for section //node_state[@uname='node2']/lrm: OK (rc=0, origin=node1/crmd/582, version=0.40.128)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section status to all (origin=local/crmd/583)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section nodes to all (origin=local/crmd/586)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section status to all (origin=local/crmd/587)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:884   )    info: cib_perform_op:   Diff: --- 0.40.128 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:886   )    info: cib_perform_op:   Diff: +++ 0.40.129 (null)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib:  @num_updates=129
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib/status/node_state[@id='2']:  @crm-debug-origin=do_lrm_query_internal
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:908   )    info: cib_perform_op:   ++ /cib/status/node_state[@id='2']:  <lrm id="2"/>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:915   )    info: cib_perform_op:   ++                                     <lrm_resources/>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:915   )    info: cib_perform_op:   ++                                   </lrm>
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section status: OK (rc=0, origin=node1/crmd/583, version=0.40.129)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section nodes: OK (rc=0, origin=node1/crmd/586, version=0.40.129)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:884   )    info: cib_perform_op:   Diff: --- 0.40.129 2
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:886   )    info: cib_perform_op:   Diff: +++ 0.40.130 (null)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib:  @num_updates=130
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib/status/node_state[@id='1']:  @crm-debug-origin=do_cib_replaced
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (       xml.c:952   )    info: cib_perform_op:   +  /cib/status/node_state[@id='2']:  @crm-debug-origin=do_cib_replaced
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section status: OK (rc=0, origin=node1/crmd/587, version=0.40.130)
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (  election.c:225   )    info: do_dc_takeover:   Taking over DC status for this partition
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_master operation for section 'all': OK (rc=0, origin=local/crmd/588, version=0.40.130)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section cib to all (origin=local/crmd/589)
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1325  )   debug: xml_patch_version_check:  Can apply patch 0.40.126 to 0.40.125
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1325  )   debug: xml_patch_version_check:  Can apply patch 0.40.127 to 0.40.126
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section cib: OK (rc=0, origin=node1/crmd/589, version=0.40.130)
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1325  )   debug: xml_patch_version_check:  Can apply patch 0.40.128 to 0.40.127
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1325  )   debug: xml_patch_version_check:  Can apply patch 0.40.129 to 0.40.128
Jun 09 17:31:25 [17194] fastvm-rhel-7-6-21 stonith-ng: (       xml.c:1325  )   debug: xml_patch_version_check:  Can apply patch 0.40.130 to 0.40.129
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: (  cib_file.c:423   )    info: cib_file_write_with_digest:       Wrote version 0.40.0 of the CIB to disk (digest: 6ebef8311746943742a847b50bbb11ef)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section crm_config to all (origin=local/crmd/591)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section crm_config: OK (rc=0, origin=node1/crmd/591, version=0.40.130)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section crm_config to all (origin=local/crmd/593)
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1113  )    info: cib_process_request:      Completed cib_modify operation for section crm_config: OK (rc=0, origin=node1/crmd/593, version=0.40.130)
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (   join_dc.c:179   )    info: join_make_offer:  Sending join-29 offer to node1
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (   join_dc.c:179   )    info: join_make_offer:  Sending join-29 offer to node2
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (   join_dc.c:212   )    info: do_dc_join_offer_all:     Waiting on join-29 requests from 2 outstanding nodes
Jun 09 17:31:25 [17193] fastvm-rhel-7-6-21        cib: ( callbacks.c:1049  )    info: cib_process_request:      Forwarding cib_modify operation for section crm_config to all (origin=local/crmd/595)
Jun 09 17:31:25 [17198] fastvm-rhel-7-6-21       crmd: (     utils.c:975   )    info: update_dc:        Set DC to node1 (3.0.14)
Comment 4 Ken Gaillot 2022-10-06 20:37:42 UTC 
Given the difficulty of backporting the changes related to the fix, and the limited scope of the problem, we will not fix this in RHEL 7
Note You need to log in before you can comment on or make changes to this bug.