[ClusterLabs] PAF not starting resource successfully after node reboot (was: How to set up fencing/stonith)
Casey Allen Shobe
caseyandgina at icloud.com
Fri May 25 09:01:30 EDT 2018
Any advice about how to fix this? I've been struggling to get things working for weeks now and I think this is the final stumbling block I need to figure out.
On May 23, 2018, at 2:22 PM, Casey & Gina <caseyandgina at icloud.com> wrote:
>>> So now my concern is this - our VM's are distributed across 32 hosts. One condition we were hoping to handle was when one of those host machines fails, due to bad memory or something else, as it is likely that not all of the nodes within a cluster are residing on the same VM host (there may even be some way to configure them to stay on separate hosts in ESX). In this case, a reset command will fail as well, I'd assume. I had thought that when the resource was fenced, it was done with an 'off' command, and that the resources would be brought up on a standby node. Is there a way to make this work?
>>
>> Configure your stonith agent to use "off" instead of "reset".
>
> I tried a setup with RESETPOWERON="1" for the external/vcenter stonith plugin. It does seem to work better, but I end up with a node that can't rejoin the cluster without being immediately rebooted, due to the PostgreSQL resource failing.
>
> I have pcsd set to auto-start at boot, but not pacemaker or corosync. After I power off the node in vSphere, the node is fenced and then powered back on. I see it show up in `pcs status` with PCSD Status of Online after a few seconds but shown as OFFLINE in the list of nodes on top since pacemaker and corosync are not running. If I then do a `pcs cluster start` on the rebooted node, it is again restarted. So I cannot get it to rejoin the cluster.
>
> The corosync log from another node in the cluster (pasted below) indicates that PostgreSQL fails to start after pacemaker/corosync are restarted (on d-gp2-dbpg0-1 in this case), but it does not seem to give any reason as to why. When I look on the failed node, I see that the PostgreSQL log is not being appended, so it doesn't seem it's ever actually trying to start it. I'm not sure where else I could try looking.
>
> Strangely, if prior to running `pcs cluster start` on the rebooted node, I sudo to postgres, copy the recovery.conf template to the data directory, and use pg_ctl to start the database, it comes up just fine in standby mode. Then if I do `pcs cluster start`, the node rejoins the cluster just fine without any problem.
>
> Can you tell me why pacemaker is failing to start PostgreSQL in standby mode based on the log data below, or how I can dig deeper into what is going on? Is this due to some misconfiguration on my part? I thought that PAF would try to do exactly what I do manually, but it doesn't seem this is the case...
>
> Actually, why is Pacemaker fencing the standby node just because the resource fails to start there? I thought only the master should be fenced if it were assumed to be broken.
>
> Thank you for any help you can provide,
> --
> Casey
>
>
> ------
> [2157] d-gp2-dbpg0-2 corosyncnotice [TOTEM ] A new membership (10.124.164.63:392) was formed. Members joined: 1
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: pcmk_quorum_notification: Membership 392: quorum retained (3)
> May 22 23:57:19 [2197] d-gp2-dbpg0-2 crmd: info: pcmk_quorum_notification: Membership 392: quorum retained (3)
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: notice: crm_update_peer_state_iter: pcmk_quorum_notification: Node d-gp2-dbpg0-1[1] - state is now member (was lost)
> May 22 23:57:19 [2197] d-gp2-dbpg0-2 crmd: notice: crm_update_peer_state_iter: pcmk_quorum_notification: Node d-gp2-dbpg0-1[1] - state is now member (was lost)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/268)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.51 2
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.52 (null)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=52
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @crm-debug-origin=peer_update_callback
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/268, version=0.35.52)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/272)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/273)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/272, version=0.35.52)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.52 2
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.53 (null)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=53
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @in_ccm=true, @crm-debug-origin=post_cache_update
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/273, version=0.35.53)
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: pcmk_cpg_membership: Node 1 joined group pacemakerd (counter=10.0)
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: pcmk_cpg_membership: Node 1 still member of group pacemakerd (peer=d-gp2-dbpg0-1, counter=10.0)
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: crm_update_peer_proc: pcmk_cpg_membership: Node d-gp2-dbpg0-1[1] - corosync-cpg is now online
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: pcmk_cpg_membership: Node 2 still member of group pacemakerd (peer=d-gp2-dbpg0-2, counter=10.1)
> May 22 23:57:19 [2189] d-gp2-dbpg0-2 pacemakerd: info: pcmk_cpg_membership: Node 3 still member of group pacemakerd (peer=d-gp2-dbpg0-3, counter=10.2)
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: pcmk_cpg_membership: Node 1 joined group attrd (counter=10.0)
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: crm_get_peer: Created entry 867f0ed1-1863-40fa-8f49-a3aeba90d9e7/0x55755bf16e60 for node d-gp2-dbpg0-1/1 (3 total)
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: crm_get_peer: Node 1 is now known as d-gp2-dbpg0-1
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: crm_get_peer: Node 1 has uuid 1
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: pcmk_cpg_membership: Node 1 still member of group attrd (peer=d-gp2-dbpg0-1, counter=10.0)
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: crm_update_peer_proc: pcmk_cpg_membership: Node d-gp2-dbpg0-1[1] - corosync-cpg is now online
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: notice: crm_update_peer_state_iter: crm_update_peer_proc: Node d-gp2-dbpg0-1[1] - state is now member (was (null))
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: pcmk_cpg_membership: Node 2 still member of group attrd (peer=d-gp2-dbpg0-2, counter=10.1)
> May 22 23:57:19 [2195] d-gp2-dbpg0-2 attrd: info: pcmk_cpg_membership: Node 3 still member of group attrd (peer=d-gp2-dbpg0-3, counter=10.2)
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: pcmk_cpg_membership: Node 1 joined group stonith-ng (counter=10.0)
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: crm_get_peer: Created entry f24c063b-0e1b-4dc6-b715-2a79a0629aa2/0x556b010e60e0 for node d-gp2-dbpg0-1/1 (3 total)
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: crm_get_peer: Node 1 is now known as d-gp2-dbpg0-1
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: crm_get_peer: Node 1 has uuid 1
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: pcmk_cpg_membership: Node 1 still member of group stonith-ng (peer=d-gp2-dbpg0-1, counter=10.0)
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: crm_update_peer_proc: pcmk_cpg_membership: Node d-gp2-dbpg0-1[1] - corosync-cpg is now online
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: notice: crm_update_peer_state_iter: crm_update_peer_proc: Node d-gp2-dbpg0-1[1] - state is now member (was (null))
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: pcmk_cpg_membership: Node 2 still member of group stonith-ng (peer=d-gp2-dbpg0-2, counter=10.1)
> May 22 23:57:19 [2193] d-gp2-dbpg0-2 stonith-ng: info: pcmk_cpg_membership: Node 3 still member of group stonith-ng (peer=d-gp2-dbpg0-3, counter=10.2)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: pcmk_cpg_membership: Node 1 joined group cib (counter=10.0)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: crm_get_peer: Created entry add315f9-0548-4c81-8245-b9d3b4d08b4d/0x55cca2b97020 for node d-gp2-dbpg0-1/1 (3 total)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: crm_get_peer: Node 1 is now known as d-gp2-dbpg0-1
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: crm_get_peer: Node 1 has uuid 1
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: pcmk_cpg_membership: Node 1 still member of group cib (peer=d-gp2-dbpg0-1, counter=10.0)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: crm_update_peer_proc: pcmk_cpg_membership: Node d-gp2-dbpg0-1[1] - corosync-cpg is now online
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: notice: crm_update_peer_state_iter: crm_update_peer_proc: Node d-gp2-dbpg0-1[1] - state is now member (was (null))
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: pcmk_cpg_membership: Node 2 still member of group cib (peer=d-gp2-dbpg0-2, counter=10.1)
> May 22 23:57:19 [2192] d-gp2-dbpg0-2 cib: info: pcmk_cpg_membership: Node 3 still member of group cib (peer=d-gp2-dbpg0-3, counter=10.2)
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: pcmk_cpg_membership: Node 1 joined group crmd (counter=10.0)
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: pcmk_cpg_membership: Node 1 still member of group crmd (peer=d-gp2-dbpg0-1, counter=10.0)
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: crm_update_peer_proc: pcmk_cpg_membership: Node d-gp2-dbpg0-1[1] - corosync-cpg is now online
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: pcmk_cpg_membership: Node 2 still member of group crmd (peer=d-gp2-dbpg0-2, counter=10.1)
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: pcmk_cpg_membership: Node 3 still member of group crmd (peer=d-gp2-dbpg0-3, counter=10.2)
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: notice: do_state_transition: State transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL origin=peer_update_callback ]
> May 22 23:57:20 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted: Peer Halt (source=do_te_invoke:168, 1)
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/274)
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.53 2
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.54 (null)
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=54
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @crmd=online, @crm-debug-origin=peer_update_callback
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/274, version=0.35.54)
> May 22 23:57:20 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/6, version=0.35.54)
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted: Node join (source=do_dc_join_offer_one:250, 1)
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: crm_update_peer_expected: do_dc_join_filter_offer: Node d-gp2-dbpg0-1[1] - expected state is now member (was down)
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-1=integrated
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-3=confirmed
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-2=integrated
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_replace: Digest matched on replace from d-gp2-dbpg0-2: e2ee1983f2386143276255bdc4db56db
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_replace: Replaced 0.35.54 with 0.35.54 from d-gp2-dbpg0-2
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_replace operation for section 'all': OK (rc=0, origin=d-gp2-dbpg0-2/crmd/276, version=0.35.54)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/277)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/278)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/277, version=0.35.54)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/278, version=0.35.54)
> May 22 23:57:21 [2197] d-gp2-dbpg0-2 crmd: info: action_synced_wait: Managed IPaddr2_meta-data_0 process 11450 exited with rc=0
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-44.raw
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_file_write_with_digest: Wrote version 0.35.0 of the CIB to disk (digest: 02cd04fe2eaf11aa3f455da2177a765f)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.JAWQvZ (digest: /var/lib/pacemaker/cib/cib.GYbAVa)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-2']/lrm to master (origin=local/crmd/279)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.54 2
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.55 (null)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: -- /cib/status/node_state[@id='2']/lrm[@id='2']
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=55
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-2']/lrm: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/279, version=0.35.55)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/280)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.55 2
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.56 (null)
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=56
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']: @crm-debug-origin=do_lrm_query_internal
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']: <lrm id="2"/>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resources>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="postgresql-10-main" type="pgsqlms" class="ocf" provider="heartbeat">
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_failure_0" operation_key="postgresql-10-main_monitor_0" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="7:0:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;7:0:7:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="14" rc-code="0" op-status="0" interval="0" last-run="1527
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_0" operation_key="postgresql-10-main_promote_0" operation="promote" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="16:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;16:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="41" rc-code="0" op-status="0" interval="0" last-run="15270322
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_monitor_15000" operation_key="postgresql-10-main_monitor_15000" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="17:14:8:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:8;17:14:8:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="44" rc-code="8" op-status="0" interval="15000" las
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="postgresql-master-vip" type="IPaddr2" class="ocf" provider="heartbeat">
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-master-vip_last_0" operation_key="postgresql-master-vip_start_0" operation="start" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="8:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;8:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="43" rc-code="0" op-status="0" interval="0" last-run="15270322
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-master-vip_monitor_10000" operation_key="postgresql-master-vip_monitor_10000" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="9:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;9:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="45" rc-code="0" op-status="0" interval="10000"
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="vfencing" type="external/vcenter" class="stonith">
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="vfencing_last_0" operation_key="vfencing_start_0" operation="st
> art" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="5:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;5:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="34" rc-code="0" op-status="0" interval="0" last-run="1527032266" last-rc-change="152703
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="vfencing_monitor_60000" operation_key="vfencing_monitor_60000"operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="6:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;6:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="36" rc-code="0" op-status="0" interval="60000" last-rc-change="152703226
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resources>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm>
> May 22 23:57:21 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/280, version=0.35.56)
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_FINALIZE_JOIN -> S_INTEGRATION [ input=I_JOIN_REQUEST cause=C_HA_MESSAGE origin=route_message ]
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted: Node join (source=do_dc_join_offer_one:250, 1)
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: do_log: FSA: Input I_JOIN_RESULT from route_message() received in state S_INTEGRATION
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/29)
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-1=integrated
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-3=confirmed
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: crmd_join_phase_log: join-2: d-gp2-dbpg0-2=integrated
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.56 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.57 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=57
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']: <transient_attributes id="1"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <instance_attributes id="status-1">
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <nvpair id="status-1-shutdown" name="shutdown" value="0"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </instance_attributes>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </transient_attributes>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/29, version=0.35.57)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 29 for shutdown: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 29 for shutdown[d-gp2-dbpg0-1]=0: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 29 for shutdown[d-gp2-dbpg0-2]=0: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 29 for shutdown[d-gp2-dbpg0-3]=0: OK (0)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.57 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.58 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: -- /cib/status/node_state[@id='1']/transient_attributes[@id='1']
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=58
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-1']/transient_attributes: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/11, version=0.35.58)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.58 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.59 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=59
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']: <transient_attributes id="1"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <instance_attributes id="status-1">
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <nvpair id="status-1-shutdown" name="shutdown" value="0"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </instance_attributes>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </transient_attributes>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/attrd/2, version=0.35.59)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.59 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.60 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=60
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/attrd/3, version=0.35.60)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_replace: Digest matched on replace from d-gp2-dbpg0-2: 55b20c22b84ba495b2aaa47e0c413465
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_replace: Replaced 0.35.60 with 0.35.60 from d-gp2-dbpg0-2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_replace operation for section 'all': OK (rc=0, origin=d-gp2-dbpg0-2/crmd/282, version=0.35.60)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/attrd/4, version=0.35.60)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.60 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.61 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=61
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/attrd/5, version=0.35.61)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/283)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/284)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/283, version=0.35.61)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/284, version=0.35.61)
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: action_synced_wait: Managed IPaddr2_meta-data_0 process 11461 exited with rc=0
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-45.raw
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_file_write_with_digest: Wrote version 0.35.0 of the CIB to disk (digest: 570c1d5717516723a1348d52e22d54a9)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.Nx9RP6 (digest: /var/lib/pacemaker/cib/cib.iQFz8k)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-1']/lrm to master (origin=local/crmd/285)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-1']/lrm: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/285, version=0.35.61)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/286)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-2']/lrm to master (origin=local/crmd/287)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/288)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.61 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.62 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=62
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @crm-debug-origin=do_lrm_query_internal, @join=member, @expected=member
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']: <lrm id="1"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resources/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/286, version=0.35.62)
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ]
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted: Peer Cancelled (source=do_te_invoke:161, 1)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.62 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.63 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: -- /cib/status/node_state[@id='2']/lrm[@id='2']
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=63
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by deletion of lrm[@id='2']: Resource state removal (cib=0.35.63, source=abort_unless_down:343, path=/cib/status/node_state[@id='2']/lrm[@id='2'], 1)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_delete operation for section //node_state[@uname='d-gp2-dbpg0-2']/lrm: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/287, version=0.35.63)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.63 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.64 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=64
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']: <lrm id="2"/>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resources>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="postgresql-10-main" type="pgsqlms" class="ocf" provider="heartbeat">
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_failure_0" operation_key="postgresql-10-main_monitor_0" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="7:0:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;7:0:7:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="14" rc-code="0" op-status="0" interval="0" last-run="1527
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_0" operation_key="postgresql-10-main_promote_0" operation="promote" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="16:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;16:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="41" rc-code="0" op-status="0" interval="0" last-run="15270322
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_monitor_15000" operation_key="postgresql-10-main_monitor_15000" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="17:14:8:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:8;17:14:8:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="44" rc-code="8" op-status="0" interval="15000" las
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="postgresql-master-vip" type="IPaddr2" class="ocf" provider="heartbeat">
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-master-vip_last_0" operation_key="postgresql-master-vip_start_0" operation="start" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="8:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;8:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="43" rc-code="0" op-status="0" interval="0" last-run="15270322
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-master-vip_monitor_10000" operation_key="postgresql-master-vip_monitor_10000" operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="9:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;9:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="45" rc-code="0" op-status="0" interval="10000"
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_resource id="vfencing" type="external/vcenter" class="stonith">
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="vfencing_last_0" operation_key="vfencing_start_0" operation="st
> art" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="5:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;5:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="34" rc-code="0" op-status="0" interval="0" last-run="1527032266" last-rc-change="152703
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="vfencing_monitor_60000" operation_key="vfencing_monitor_60000"operation="monitor" crm-debug-origin="build_active_RAs" crm_feature_set="3.0.10" transition-key="6:14:0:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:0;6:14:0:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-2" call-id="36" rc-code="0" op-status="0" interval="60000" last-rc-change="152703226
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resources>
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm>
> May 22 23:57:22 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted: LRM Refresh (source=process_resource_updates:266, 1)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/288, version=0.35.64)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section nodes to master (origin=local/crmd/292)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/293)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/30)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/31)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/292, version=0.35.64)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.64 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.65 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=65
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='3']: @crm-debug-origin=do_state_transition
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @crm-debug-origin=do_state_transition
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']: @crm-debug-origin=do_state_transition
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/293, version=0.35.65)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.65 2
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.66 (null)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=66
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/30, version=0.35.66)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 30 for terminate: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 30 for terminate[d-gp2-dbpg0-1]=(null): OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 30 for terminate[d-gp2-dbpg0-2]=(null): OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 30 for terminate[d-gp2-dbpg0-3]=(null): OK (0)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/31, version=0.35.66)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 31 for shutdown: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 31 for shutdown[d-gp2-dbpg0-1]=0: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 31 for shutdown[d-gp2-dbpg0-2]=0: OK (0)
> May 22 23:57:22 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 31 for shutdown[d-gp2-dbpg0-3]=0: OK (0)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section cib to master (origin=local/crmd/294)
> May 22 23:57:22 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section cib: OK (rc=0, origin=d-gp2-dbpg0-2/crmd/294, version=0.35.66)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-3 is active
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-3 is online
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-1 is active
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-1 is online
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-2 is active
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-2 is online
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: determine_op_status: Operation monitor found resource postgresql-10-main:1 active on d-gp2-dbpg0-2
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: native_print: vfencing (stonith:external/vcenter): Started d-gp2-dbpg0-2
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-master-vip (ocf::heartbeat:IPaddr2): Started d-gp2-dbpg0-2
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: clone_print: Master/Slave Set: postgresql-ha [postgresql-10-main]
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Masters: [ d-gp2-dbpg0-2 ]
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Slaves: [ d-gp2-dbpg0-3 ]
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Stopped: [ d-gp2-dbpg0-1 ]
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: master_color: Promoting postgresql-10-main:1 (Master d-gp2-dbpg0-2)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: master_color: postgresql-ha: Promoted 1 instances of a possible 1 to master
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: RecurringOp: Start recurring monitor (16s) for postgresql-10-main:2 on d-gp2-dbpg0-1
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: RecurringOp: Start recurring monitor (16s) for postgresql-10-main:2 on d-gp2-dbpg0-1
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave vfencing (Started d-gp2-dbpg0-2)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-master-vip (Started d-gp2-dbpg0-2)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:0 (Slave d-gp2-dbpg0-3)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:1 (Master d-gp2-dbpg0-2)
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Start postgresql-10-main:2 (d-gp2-dbpg0-1)
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
> May 22 23:57:23 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:60
> May 22 23:57:23 [2196] d-gp2-dbpg0-2 pengine: notice: process_pe_message: Calculated Transition 26: /var/lib/pacemaker/pengine/pe-input-89.bz2
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.66 2
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.67 (null)
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=67
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']: @crm-debug-origin=do_update_resource
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources: <lrm_resource id="vfencing" type="external/vcenter" class="stonith"/>
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="vfencing_last_0" operation_key="vfencing_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="6:26:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:7;6:26:7:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-1" call-id="5" rc-code="7" op-status="0" interval="0" last-run="152703
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/14, version=0.35.67)
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.67 2
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.68 (null)
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=68
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources: <lrm_resource id="postgresql-master-vip" type="IPaddr2" cl
> ass="ocf" provider="heartbeat"/>
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-master-vip_last_0" operation_key="postgresql-master-vip_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="7:26:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:7;7:26:7:0df60493-9320-463d-94ca-a9515d139f9f" on_node="d-gp2-dbpg0-1" call-id="9" rc-code="7" op-status="0" int
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/15, version=0.35.68)
> May 22 23:57:23 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:60 pid:11472 exit-code:0 exec-time:97ms queue-time:0ms
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=60, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.68 2
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.69 (null)
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=69
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources: <lrm_resource id="postgresql-10-main" type="pgsqlms" class="ocf" provider="heartbeat"/>
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_failure_0" operation_key="postgresql-10-main_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="8:26:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:9;8:26:7:0df60493-9320-463d-94ca-a9515d139f9f" exit-reason="Instance "postgresql-10-main" controldat
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ <lrm_rsc_op id="postgresql-10-main_last_0" operation_key="postgresql-10-main_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="8:26:7:0df60493-9320-463d-94ca-a9515d139f9f" transition-magic="0:9;8:26:7:0df60493-9320-463d-94ca-a9515d139f9f" exit-reason="Instance "postgresql-10-main" controldata indica
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ </lrm_resource>
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by postgresql-10-main_monitor_0 'create' on d-gp2-dbpg0-1: Event failed (magic=0:9;8:26:7:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.69, source=match_graph_event:381, 0)
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by postgresql-10-main_monitor_0 'create' on d-gp2-dbpg0-1: Event failed (magic=0:9;8:26:7:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.69, source=match_graph_event:381, 0)
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: notice: run_graph: Transition 26 (Complete=7, Pending=0, Fired=0, Skipped=0, Incomplete=9, Source=/var/lib/pacemaker/pengine/pe-input-89.bz2): Complete
> May 22 23:57:23 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
> May 22 23:57:23 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/16, version=0.35.69)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-3 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-3 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-1 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-1 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-2 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-2 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op monitor for postgresql-10-main:1 on d-gp2-dbpg0-1: master (failed) (9)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op monitor for postgresql-10-main:1 on d-gp2-dbpg0-1: master (failed) (9)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_op_status: Operation monitor found resource postgresql-10-main:2 active on d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: vfencing (stonith:external/vcenter): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-master-vip (ocf::heartbeat:IPaddr2): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: clone_print: Master/Slave Set: postgresql-ha [postgresql-10-main]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-10-main (ocf::heartbeat:pgsqlms): FAILED Master d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Masters: [ d-gp2-dbpg0-2 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Slaves: [ d-gp2-dbpg0-3 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: Promoting postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: postgresql-ha: Promoted 1 instances of a possible 1 to master
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: RecurringOp: Start recurring monitor (16s) for postgresql-10-main:1 on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: RecurringOp: Start recurring monitor (16s) for postgresql-10-main:1 on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave vfencing (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-master-vip (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:0 (Slave d-gp2-dbpg0-3)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Demote postgresql-10-main:1 (Master -> Slave d-gp2-dbpg0-1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Recover postgresql-10-main:1 (Master d-gp2-dbpg0-1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:61
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: process_pe_message: Calculated Transition 27: /var/lib/pacemaker/pengine/pe-input-90.bz2
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:61 pid:11484 exit-code:0 exec-time:101ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=61, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.69 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.70 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=70
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_failure_0']: @operation_key=postgresql-10-main_demote_0, @operation=demote, @transition-key=13:27:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;13:27:0:0df60493-9320-463d-94ca-a9515d139f9f, @call-id=16, @rc-code=1, @last-run=1527033444, @last-rc-change=1527033444, @exec-time=90
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_0']: @operation_key=postgresql-10-main_demote_0, @operation=demote, @transition-key=13:27:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;13:27:0:0df60493-9320-463d-94c
> a-a9515d139f9f, @call-id=16, @rc-code=1, @last-run=1527033444, @last-rc-change=1527033444, @exec-time=90
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/17, version=0.35.70)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by postgresql-10-main_demote_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;13:27:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.70, source=match_graph_event:381, 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/32)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.70 2
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by postgresql-10-main_demote_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;13:27:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.70, source=match_graph_event:381, 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.71 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=71
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']: <nvpair id="status-1-fail-count-postgresql-10-main" name="fail-count-postgresql-10-main" value="1"/>
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/32, version=0.35.71)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 32 for fail-count-postgresql-10-main: OK (0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 32 for fail-count-postgresql-10-main[d-gp2-dbpg0-1]=1: OK (0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/33)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/34)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:62
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by status-1-fail-count-postgresql-10-main, fail-count-postgresql-10-main=1: Transient attribute change (create cib=0.35.71, source=abort_unless_down:329, path=/cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1'], 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.71 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.72 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=72
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']: <nvpair id="status-1-last-failure-postgresql-10-main" name="last-failure-postgresql-10-main" value="1527033444"/>
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/33, version=0.35.72)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by status-1-last-failure-postgresql-10-main, last-failure-postgresql-10-main=1527033444: Transient attribute change (create cib=0.35.72, source=abort_unless_down:329, path=/cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1'], 0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 33 for last-failure-postgresql-10-main: OK (0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 33 for last-failure-postgresql-10-main[d-gp2-dbpg0-1]=1527033444: OK (0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.72 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.73 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=73
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main']: @value=2
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by status-1-fail-count-postgresql-10-main, fail-count-postgresql-10-main=2: Transient attribute change (modify cib=0.35.73, source=abort_unless_down:329, path=/cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main'], 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/34, version=0.35.73)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 34 for fail-count-postgresql-10-main: OK (0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 34 for fail-count-postgresql-10-main[d-gp2-dbpg0-1]=2: OK (0)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:62 pid:11496 exit-code:0 exec-time:86ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=62, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: run_graph: Transition 27 (Complete=14, Pending=0, Fired=0, Skipped=3, Incomplete=25, Source=/var/lib/pacemaker/pengine/pe-input-90.bz2): Stopped
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-3 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-3 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-1 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-1 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-2 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-2 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op demote for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Forcing postgresql-10-main:1 to stop after a failed demote action
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op demote for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Forcing postgresql-10-main:1 to stop after a failed demote action
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_op_status: Operation monitor found resource postgresql-10-main:2 active on d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: vfencing (stonith:external/vcenter): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-master-vip (ocf::heartbeat:IPaddr2): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: clone_print: Master/Slave Set: postgresql-ha [postgresql-10-main]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-10-main (ocf::heartbeat:pgsqlms): FAILED d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Masters: [ d-gp2-dbpg0-2 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Slaves: [ d-gp2-dbpg0-3 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:0 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:1 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:2 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_color: Resource postgresql-10-main:1 cannot run anywhere
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: Promoting postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: postgresql-ha: Promoted 1 instances of a possible 1 to master
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave vfencing (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-master-vip (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:0 (Slave d-gp2-dbpg0-3)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Stop postgresql-10-main:1 (d-gp2-dbpg0-1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:63
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: process_pe_message: Calculated Transition 28: /var/lib/pacemaker/pengine/pe-input-91.bz2
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:63 pid:11508 exit-code:0 exec-time:79ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=63, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.73 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.74 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=74
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_failure_0']: @operation_key=postgresql-10-main_stop_0, @operation=stop, @transition-key=2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @exit-reason=Unexpected state for instance "postgresql-10-main" (returned 9), @call-id=19, @ex
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_0']: @operation_key=postgresql-10-main_stop_0, @operation=stop, @transition-key=2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @exit-reason=Unexpected state for instance "postgresql-10-main" (returned 9), @call-id=19, @exec-time=
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by postgresql-10-main_stop_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.74, source=match_graph_event:381, 0)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by postgresql-10-main_stop_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.74, source=match_graph_event:381, 0)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:64
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/18, version=0.35.74)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/35)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.74 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.75 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=75
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main']: @value=INFINITY
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by status-1-fail-count-postgresql-10-main, fail-count-postgresql-10-main=INFINITY: Transient attribute change (modify cib=0.35.75, source=abort_unless_down:329, path=/cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main'], 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/35, version=0.35.75)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 35 for fail-count-postgresql-10-main: OK (0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 35 for fail-count-postgresql-10-main[d-gp2-dbpg0-1]=INFINITY: OK (0)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:64 pid:11560 exit-code:0 exec-time:77ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=64, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: run_graph: Transition 28 (Complete=12, Pending=0, Fired=0, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-91.bz2): Complete
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-3 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-3 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-1 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-1 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-2 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-2 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op stop for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op stop for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: pe_fence_node: Node d-gp2-dbpg0-1 will be fenced because of resource failure(s)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_op_status: Operation monitor found resource postgresql-10-main:2 active on d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: vfencing (stonith:external/vcenter): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-master-vip (ocf::heartbeat:IPaddr2): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: clone_print: Master/Slave Set: postgresql-ha [postgresql-10-main]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-10-main (ocf::heartbeat:pgsqlms): FAILED d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Masters: [ d-gp2-dbpg0-2 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Slaves: [ d-gp2-dbpg0-3 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:0 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:1 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:2 has failed 2 times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: common_apply_stickiness: postgresql-ha can fail 3 more times on d-gp2-dbpg0-1 before being forced off
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_color: Resource postgresql-10-main:1 cannot run anywhere
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: Promoting postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: postgresql-ha: Promoted 1 instances of a possible 1 to master
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave vfencing (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-master-vip (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:0 (Slave d-gp2-dbpg0-3)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Stop postgresql-10-main:1 (d-gp2-dbpg0-1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:63
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: process_pe_message: Calculated Transition 28: /var/lib/pacemaker/pengine/pe-input-91.bz2
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:63 pid:11508 exit-code:0 exec-time:79ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=63, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.73 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.74 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=74
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_failure_0']: @operation_key=postgresql-10-main_stop_0, @operation=stop, @transition-key=2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @exit-reason=Unexpected state for instance "postgresql-10-main" (returned 9), @call-id=19, @ex
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='postgresql-10-main']/lrm_rsc_op[@id='postgresql-10-main_last_0']: @operation_key=postgresql-10-main_stop_0, @operation=stop, @transition-key=2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @transition-magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, @exit-reason=Unexpected state for instance "postgresql-10-main" (returned 9), @call-id=19, @exec-time=
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by postgresql-10-main_stop_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.74, source=match_graph_event:381, 0)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: abort_transition_graph: Transition aborted by postgresql-10-main_stop_0 'modify' on d-gp2-dbpg0-1: Event failed (magic=0:1;2:28:0:0df60493-9320-463d-94ca-a9515d139f9f, cib=0.35.74, source=match_graph_event:381, 0)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:64
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-1/crmd/18, version=0.35.74)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/35)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: --- 0.35.74 2
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: Diff: +++ 0.35.75 (null)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib: @num_updates=75
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main']: @value=INFINITY
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: abort_transition_graph: Transition aborted by status-1-fail-count-postgresql-10-main, fail-count-postgresql-10-main=INFINITY: Transient attribute change (modify cib=0.35.75, source=abort_unless_down:329, path=/cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']/nvpair[@id='status-1-fail-count-postgresql-10-main'], 0)
> May 22 23:57:24 [2192] d-gp2-dbpg0-2 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=d-gp2-dbpg0-2/attrd/35, version=0.35.75)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 35 for fail-count-postgresql-10-main: OK (0)
> May 22 23:57:24 [2195] d-gp2-dbpg0-2 attrd: info: attrd_cib_callback: Update 35 for fail-count-postgresql-10-main[d-gp2-dbpg0-1]=INFINITY: OK (0)
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:64 pid:11560 exit-code:0 exec-time:77ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=64, rc=0, cib-update=0, confirmed=true)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: run_graph: Transition 28 (Complete=12, Pending=0, Fired=0, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-91.bz2): Complete
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-3 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-3 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-1 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-1 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status_fencing: Node d-gp2-dbpg0-2 is active
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_online_status: Node d-gp2-dbpg0-2 is online
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op stop for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: unpack_rsc_op_failure: Processing failed op stop for postgresql-10-main:1 on d-gp2-dbpg0-1: unknown error (1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: pe_fence_node: Node d-gp2-dbpg0-1 will be fenced because of resource failure(s)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: determine_op_status: Operation monitor found resource postgresql-10-main:2 active on d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: vfencing (stonith:external/vcenter): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-master-vip (ocf::heartbeat:IPaddr2): Started d-gp2-dbpg0-2
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: clone_print: Master/Slave Set: postgresql-ha [postgresql-10-main]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_print: postgresql-10-main (ocf::heartbeat:pgsqlms): FAILED d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Masters: [ d-gp2-dbpg0-2 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: short_print: Slaves: [ d-gp2-dbpg0-3 ]
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:0 has failed INFINITY times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: common_apply_stickiness: Forcing postgresql-ha away from d-gp2-dbpg0-1 after 1000000 failures (max=5)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:1 has failed INFINITY times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: common_apply_stickiness: Forcing postgresql-ha away from d-gp2-dbpg0-1 after 1000000 failures (max=5)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: get_failcount_full: postgresql-10-main:2 has failed INFINITY times on d-gp2-dbpg0-1
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: common_apply_stickiness: Forcing postgresql-ha away from d-gp2-dbpg0-1 after 1000000 failures (max=5)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_color: Resource postgresql-10-main:1 cannot run anywhere
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: Promoting postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: master_color: postgresql-ha: Promoted 1 instances of a possible 1 to master
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: stage6: Scheduling Node d-gp2-dbpg0-1 for STONITH
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: native_stop_constraints: Stop of failed resource postgresql-10-main:1 is implicit after d-gp2-dbpg0-1 is fenced
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: native_stop_constraints: Creating secondary notification for postgresql-10-main:1_stop_0
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave vfencing (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-master-vip (Started d-gp2-dbpg0-2)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:0 (Slave d-gp2-dbpg0-3)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: notice: LogActions: Stop postgresql-10-main:1 (d-gp2-dbpg0-1)
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: info: LogActions: Leave postgresql-10-main:2 (Master d-gp2-dbpg0-2)
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_execute: executing - rsc:postgresql-10-main action:notify call_id:65
> May 22 23:57:24 [2196] d-gp2-dbpg0-2 pengine: warning: process_pe_message: Calculated Transition 29: /var/lib/pacemaker/pengine/pe-warn-12.bz2
> May 22 23:57:24 [2194] d-gp2-dbpg0-2 lrmd: info: log_finished: finished - rsc:postgresql-10-main action:notify call_id:65 pid:11573 exit-code:0 exec-time:160ms queue-time:0ms
> May 22 23:57:24 [2197] d-gp2-dbpg0-2 crmd: notice: process_lrm_event: Operation postgresql-10-main_notify_0: ok (node=d-gp2-dbpg0-2, call=65, rc=0, cib-update=0, confirmed=true)
> _______________________________________________
> Users mailing list: Users at clusterlabs.org
> https://lists.clusterlabs.org/mailman/listinfo/users
>
> Project Home: http://www.clusterlabs.org
> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
> Bugs: http://bugs.clusterlabs.org
More information about the Users
mailing list