[ClusterLabs] Fwd: Postgres pacemaker cluster failure
Danka Ivanović
danka.ivanovic at gmail.com
Tue Jul 9 06:08:56 EDT 2019
Hi I didn't manage to start master with postgres, even if I increased start
timeout. I checked executable paths and start options.
When cluster is running with manually started master and slave started over
pacemaker, everything works ok. Today we had failover again.
I cannot find reason from the logs, can you help me with debugging? Thanks.
Jul 09 09:16:34 [2681] postgres1 pengine: warning: unpack_rsc_op_failure:
Processing failed op monitor for PGSQL:0 on postgres1: unknown error (1)
-
On Thu, 16 May 2019 at 17:12, Ken Gaillot <kgaillot at redhat.com> wrote:
> On Thu, 2019-05-16 at 10:20 +0200, Jehan-Guillaume de Rorthais wrote:
> > On Wed, 15 May 2019 16:53:48 -0500
> > Ken Gaillot <kgaillot at redhat.com> wrote:
> >
> > > On Wed, 2019-05-15 at 11:50 +0200, Jehan-Guillaume de Rorthais
> > > wrote:
> > > > On Mon, 29 Apr 2019 19:59:49 +0300
> > > > Andrei Borzenkov <arvidjaar at gmail.com> wrote:
> > > >
> > > > > 29.04.2019 18:05, Ken Gaillot пишет:
> > > > > > >
> > > > > > > > Why does not it check OCF_RESKEY_CRM_meta_notify?
> > > > > > >
> > > > > > > I was just not aware of this env variable. Sadly, it is not
> > > > > > > documented
> > > > > > > anywhere :(
> > > > > >
> > > > > > It's not a Pacemaker-created value like the other notify
> > > > > > variables --
> > > > > > all user-specified meta-attributes are passed that way. We do
> > > > > > need to
> > > > > > document that.
> > > > >
> > > > > OCF_RESKEY_CRM_meta_notify is passed also when "notify" meta-
> > > > > attribute
> > > > > is *not* specified, as well as a couple of others. But not
> > > > > all
> > >
> > > Hopefully in that case it's passed as false? I vaguely remember
> > > some
> > > case where clone attributes were mistakenly passed to non-clone
> > > resources, but I think notify is always accurate for clone
> > > resources.
> >
> > [1]
> >
> > > > > possible
> > > > > attributes. And some OCF_RESKEY_CRM_meta_* variables that are
> > > > > passed do
> > > > > not correspond to any user settable and documented meta-
> > > > > attribute,
> > > > > like
> > > > > OCF_RESKEY_CRM_meta_clone.
> > > >
> > > > Sorry guys, now I am confused.
> > >
> > > A well-known side effect of pacemaker ;)
> > >
> > > > Is it safe or not to use OCF_RESKEY_CRM_meta_notify? You both
> > > > doesn't
> > > > seem to
> > > > agree where it comes from. Is it only a non expected side effect
> > > > or
> > > > is it safe
> > > > and stable code path in Pacemaker we can rely on?
> > >
> > > It's reliable. All user-specified meta-attributes end up as
> > > environment
> > > variables
> >
> > OK...
> >
> > > -- it's just meta-attributes that *aren't* specified by the
> > > user that may or may not show up
> >
> > OK...
> >
> > > (but hopefully with the correct value).
> >
> > And that's where I am now loosing some confidence about this
> > environment vars :)
> > "Hopefully" and "I think is accurate" ([1]) are quite scary to me :/
>
> It looks perfectly reliable to me :) but Andrei's comments make me want
> more information.
>
> If I understand correctly, he's saying that the presence of the notify
> variable is unreliable. That's fine if the option is not specified by
> the user, and the variable is either not present or present as false.
> But it would indicate a bug if the variable is not present when the
> option *is* specified by the user, or if the variable is present as
> true when the option is not specified by the user.
>
> Personally I'd rely on it.
>
> The controller gets the environment variable values from the
> <attributes> entries in the scheduler's result. We have numerous
> examples in the scheduler regression test data, typically installed
> under /usr/share/pacemaker/tests in scheduler/*.exp (for 2.0) or
> pengine/test10/*.exp (for 1.1).
> --
> Ken Gaillot <kgaillot at redhat.com>
>
> _______________________________________________
> Manage your subscription:
> https://lists.clusterlabs.org/mailman/listinfo/users
>
> ClusterLabs home: https://www.clusterlabs.org/
--
Pozdrav
Danka Ivanovic
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clusterlabs.org/pipermail/users/attachments/20190709/1cfdb877/attachment-0001.html>
-------------- next part --------------
Jul 09 09:16:07 [2679] postgres1 lrmd: debug: recurring_action_timer: Scheduling another invocation of PGSQL_monitor_15000
Jul 09 09:16:07 [12704] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:07 [12704] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12704-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12704]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12704-24)
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12704-24) state:2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-12704-24-header
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12704-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12704]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12704-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12704-24) state:2
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12704] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-12704-24-header
Jul 09 09:16:07 [12704] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-12704-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-12704-24-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=12706 id=0d7c9e17-912c-4f8b-be86-cf0c8d5be753
Jul 09 09:16:07 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-12706-13)
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [12706]
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:16:07 [12706] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12706-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-12706-13)
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12706-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-12706-13) state:2
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:07 [12706] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12706-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12706-13-header
Jul 09 09:16:07 [12706] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12706-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12706-13-header
Jul 09 09:16:07 [12713] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:07 [12713] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:07 [12713] postgres1 crm_node: debug: main: Attempting to process -p command for cluster type: corosync
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: crm_client_new: Connecting 0x55d9f52f9970 for uid=0 gid=0 pid=12713 id=a062f602-1a5f-432f-acb2-fe8aeb2c3136
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: handle_new_connection: IPC credentials authenticated (2675-12713-10)
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_ipcs_shm_connect: connecting to client [12713]
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [12713] postgres1 crm_node: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [12713] postgres1 crm_node: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [12713] postgres1 crm_node: debug: qb_rb_open_2: shm size:131085; real_size:135168; rb->word_size:33792
Jul 09 09:16:07 [12713] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_ipcs_dispatch_connection_request: HUP conn (2675-12713-10)
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2675-12713-10) state:2
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-pacemakerd-response-2675-12713-10-header
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-pacemakerd-event-2675-12713-10-header
Jul 09 09:16:07 [2675] postgres1 pacemakerd: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-pacemakerd-request-2675-12713-10-header
Jul 09 09:16:07 [12718] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:07 [12718] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12718-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12718]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12718-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12718-24) state:2
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-12718-24-header
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12718-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12718]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12718-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12718-24) state:2
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12718] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-12718-24-header
Jul 09 09:16:07 [12718] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-12718-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-12718-24-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=12720 id=8e357a84-a7af-40db-8103-91048dd5d1fb
Jul 09 09:16:07 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-12720-13)
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [12720]
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nodes>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <node id="1" uname="postgres2">
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <instance_attributes id="nodes-1">
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nvpair id="nodes-1-master-PGSQL" name="master-PGSQL" value="1000"/>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </instance_attributes>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </node>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <node id="2" uname="postgres1">
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <instance_attributes id="nodes-2">
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nvpair id="nodes-2-master-PGSQL" name="master-PGSQL" value="1001"/>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </instance_attributes>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </node>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </nodes>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: info: query_node_uuid: Mapped postgres2 to 1
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_process_xpath: Processing cib_query op for //cib/configuration/nodes//node[@id='1']//instance_attributes//nvpair[@name='master-PGSQL'] (/cib/configuration/nodes/node[1]/instance_attributes/nvpair)
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: find_nvpair_attr_delegate: Match <nvpair id="nodes-1-master-PGSQL" name="master-PGSQL" value="1000"/>
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12720-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-12720-13)
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-12720-13) state:2
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12720-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12720-13-header
Jul 09 09:16:07 [12720] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12720-13-header
Jul 09 09:16:07 [12720] postgres1 crm_attribute: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12720-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12720-13-header
Jul 09 09:16:07 [12723] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:07 [12723] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12723-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12723]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12723-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12723-24) state:2
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-12723-24-header
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12723-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] connecting to client [12723]
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-12723-24-header
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12723-24)
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12723-24) state:2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:07 [12723] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-12723-24-header
Jul 09 09:16:07 [12723] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-12723-24-header
Jul 09 09:16:07 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-12723-24-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=12725 id=5b2f9276-0c34-4fda-b7d0-49969136f574
Jul 09 09:16:07 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-12725-13)
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [12725]
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nodes>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <node id="1" uname="postgres2">
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <instance_attributes id="nodes-1">
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nvpair id="nodes-1-master-PGSQL" name="master-PGSQL" value="1000"/>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </instance_attributes>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </node>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <node id="2" uname="postgres1">
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <instance_attributes id="nodes-2">
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section <nvpair id="nodes-2-master-PGSQL" name="master-PGSQL" value="1001"/>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </instance_attributes>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </node>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: get_cluster_node_uuid: Result section </nodes>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: info: query_node_uuid: Mapped postgres1 to 2
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:07 [2677] postgres1 cib: debug: cib_process_xpath: Processing cib_query op for //cib/configuration/nodes//node[@id='2']//instance_attributes//nvpair[@name='master-PGSQL'] (/cib/configuration/nodes/node[2]/instance_attributes/nvpair)
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: find_nvpair_attr_delegate: Match <nvpair id="nodes-2-master-PGSQL" name="master-PGSQL" value="1001"/>
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12725-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-12725-13)
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-12725-13) state:2
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12725-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:07 [12725] postgres1 crm_attribute: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12725-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12725-13-header
Jul 09 09:16:07 [12725] postgres1 crm_attribute: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12725-13-header
Jul 09 09:16:07 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12725-13-header
Jul 09 09:16:07 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_monitor_15000:12697 - exited with rc=8
Jul 09 09:16:07 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_monitor_15000:12697:stderr [ -- empty -- ]
Jul 09 09:16:07 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_monitor_15000:12697:stdout [ /var/run/postgresql/:5432 - accepting connections ]
Jul 09 09:16:07 [2679] postgres1 lrmd: debug: log_finished: finished - rsc:PGSQL action:monitor call_id:43 pid:12697 exit-code:8 exec-time:0ms queue-time:0ms
Jul 09 09:16:22 [2679] postgres1 lrmd: debug: recurring_action_timer: Scheduling another invocation of PGSQL_monitor_15000
Jul 09 09:16:22 [12742] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:22 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Jul 09 09:16:34 [12742] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:32 [2679] postgres1 lrmd: debug: child_kill_helper: Kill pid 12735's group
Jul 09 09:16:34 [2679] postgres1 lrmd: warning: child_timeout_callback: PGSQL_monitor_15000 process (PID 12735) timed out
Jul 09 09:16:34 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.590000 (full: 0.59 0.25 0.17 4/449 12747)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:16:34 [2679] postgres1 lrmd: warning: operation_finished: PGSQL_monitor_15000:12735 - timed out after 10000ms
Jul 09 09:16:34 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_monitor_15000:12735:stderr [ -- empty -- ]
Jul 09 09:16:34 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_monitor_15000:12735:stdout [ -- empty -- ]
Jul 09 09:16:34 [2679] postgres1 lrmd: debug: log_finished: finished - rsc:PGSQL action:monitor call_id:43 pid:12735 exit-code:1 exec-time:0ms queue-time:0ms
Jul 09 09:16:34 [2682] postgres1 crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after monitor op Timed Out (interval=15000)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: update_history_cache: Updating history for 'PGSQL' with monitor op
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/951)
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.1 2
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.2 (null)
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=2
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']: @crm-debug-origin=do_update_resource
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_last_failure_0']: @operation_key=PGSQL_monitor_15000, @crm-debug-origin=do_update_resource, @transition-key=11:16:8:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=2:1;11:16:8:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=43, @rc-code=1, @op-status=2, @interval=15000, @last-rc-change=1562663794, @exec-tim
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/crmd/951, version=0.117.2)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.1 -> 0.117.2 (S_IDLE)
Jul 09 09:16:34 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by PGSQL_monitor_15000 'modify' on postgres1: Old event (magic=2:1;11:16:8:ea56a968-bf94-4167-a81f-67a85176c75b, cib=0.117.2, source=process_graph_event:605, 1)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: fail-count-PGSQL=value++ for postgres1
Jul 09 09:16:34 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: last-failure-PGSQL=1562663794 for postgres1
Jul 09 09:16:34 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Jul 09 09:16:34 [2682] postgres1 crmd: notice: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_state_transition: All 2 cluster nodes are eligible to run resources.
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_pe_invoke: Query 952: Requesting the current CIB: S_POLICY_ENGINE
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.2 to 0.117.1
Jul 09 09:16:34 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting fail-count-PGSQL[postgres1] = 1 (writer)
Jul 09 09:16:34 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting last-failure-PGSQL[postgres1] = 1562663794 (writer)
Jul 09 09:16:34 [2680] postgres1 attrd: debug: write_attribute: Update: postgres1[fail-count-PGSQL]=1 (2 2 2 postgres1)
Jul 09 09:16:34 [2680] postgres1 attrd: debug: write_attribute: Update: postgres1[last-failure-PGSQL]=1562663794 (2 2 2 postgres1)
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/25)
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/26)
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.2 2
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.3 (null)
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=3
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']: <nvpair id="status-2-fail-count-PGSQL" name="fail-count-PGSQL" value="1"/>
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/attrd/25, version=0.117.3)
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.3 to 0.117.2
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_pe_invoke_callback: Invoking the PE: query=952, ref=pe_calc-dc-1562663794-909, seq=76, quorate=1
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.3 2
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.4 (null)
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=4
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']: <nvpair id="status-2-last-failure-PGSQL" name="last-failure-PGSQL" value="1562663794"/>
Jul 09 09:16:34 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/attrd/26, version=0.117.4)
Jul 09 09:16:34 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.4 to 0.117.3
Jul 09 09:16:34 [2680] postgres1 attrd: info: attrd_cib_callback: Update 25 for fail-count-PGSQL: OK (0)
Jul 09 09:16:34 [2680] postgres1 attrd: info: attrd_cib_callback: Update 25 for fail-count-PGSQL[postgres1]=1: OK (0)
Jul 09 09:16:34 [2680] postgres1 attrd: info: attrd_cib_callback: Update 26 for last-failure-PGSQL: OK (0)
Jul 09 09:16:34 [2680] postgres1 attrd: info: attrd_cib_callback: Update 26 for last-failure-PGSQL[postgres1]=1562663794: OK (0)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.2 -> 0.117.3 (S_POLICY_ENGINE)
Jul 09 09:16:34 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by status-2-fail-count-PGSQL, fail-count-PGSQL=1: Transient attribute change (create cib=0.117.3, source=abort_unless_down:329, path=/cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2'], 1)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.3 -> 0.117.4 (S_POLICY_ENGINE)
Jul 09 09:16:34 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by status-2-last-failure-PGSQL, last-failure-PGSQL=1562663794: Transient attribute change (create cib=0.117.4, source=abort_unless_down:329, path=/cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2'], 1)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_POLICY_ENGINE cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_pe_invoke: Query 953: Requesting the current CIB: S_POLICY_ENGINE
Jul 09 09:16:34 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_POLICY_ENGINE cause=C_FSA_INTERNAL origin=abort_transition_graph ]
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_pe_invoke: Query 954: Requesting the current CIB: S_POLICY_ENGINE
Jul 09 09:16:34 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: Stop all active resources: false
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: Default stickiness: 0
Jul 09 09:16:34 [2681] postgres1 pengine: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:16:34 [2681] postgres1 pengine: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_online_status: Node postgres1 is online
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_online_status: Node postgres2 is online
Jul 09 09:16:34 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:16:34 [2681] postgres1 pengine: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:34 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Processing failed op monitor for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:16:34 [2682] postgres1 crmd: debug: do_pe_invoke_callback: Invoking the PE: query=954, ref=pe_calc-dc-1562663794-910, seq=76, quorate=1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:16:34 [2681] postgres1 pengine: info: native_print: fencing-postgres2 (stonith:external/ec2): Started postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: info: native_print: AWSVIP (ocf::heartbeat:awsvip): Started postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: info: clone_print: Master/Slave Set: PGSQL-HA [PGSQL]
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:0 active on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: info: native_print: PGSQL (ocf::heartbeat:pgsqlms): FAILED Master postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:16:34 [2681] postgres1 pengine: info: short_print: Slaves: [ postgres2 ]
Jul 09 09:16:34 [2681] postgres1 pengine: info: native_print: fencing-postgres1 (stonith:external/ec2): Started postgres2
Jul 09 09:16:34 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres2: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource AWSVIP: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:0: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:1: preferring current location (node=postgres2, weight=10)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres1: preferring current location (node=postgres2, weight=10)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to fencing-postgres2
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to PGSQL:1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to PGSQL:0
Jul 09 09:16:34 [2681] postgres1 pengine: debug: clone_color: Allocated 2 PGSQL-HA instances of a possible 2
Jul 09 09:16:34 [2681] postgres1 pengine: debug: master_color: PGSQL:0 master score: 1001
Jul 09 09:16:34 [2681] postgres1 pengine: info: master_color: Promoting PGSQL:0 (Master postgres1)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: master_color: PGSQL:1 master score: 1000
Jul 09 09:16:34 [2681] postgres1 pengine: info: master_color: PGSQL-HA: Promoted 1 instances of a possible 1 to master
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to AWSVIP
Jul 09 09:16:34 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to fencing-postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: debug: master_create_actions: Creating actions for PGSQL-HA
Jul 09 09:16:34 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:0 on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:0 on postgres1
Jul 09 09:16:34 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres2 (Started postgres1)
Jul 09 09:16:34 [2681] postgres1 pengine: info: LogActions: Leave AWSVIP (Started postgres1)
Jul 09 09:16:34 [2681] postgres1 pengine: notice: LogActions: Recover PGSQL:0 (Master postgres1)
Jul 09 09:16:34 [2681] postgres1 pengine: info: LogActions: Leave PGSQL:1 (Slave postgres2)
Jul 09 09:16:34 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres1 (Started postgres2)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:34 [2681] postgres1 pengine: notice: process_pe_message: Calculated Transition 793: /var/lib/pacemaker/pengine/pe-input-20.bz2
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: Stop all active resources: false
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: Default stickiness: 0
Jul 09 09:16:35 [2681] postgres1 pengine: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:16:35 [2681] postgres1 pengine: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_online_status: Node postgres1 is online
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_online_status: Node postgres2 is online
Jul 09 09:16:35 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:16:35 [2681] postgres1 pengine: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Processing failed op monitor for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:16:35 [2681] postgres1 pengine: info: native_print: fencing-postgres2 (stonith:external/ec2): Started postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: info: native_print: AWSVIP (ocf::heartbeat:awsvip): Started postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: info: clone_print: Master/Slave Set: PGSQL-HA [PGSQL]
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:0 active on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: info: native_print: PGSQL (ocf::heartbeat:pgsqlms): FAILED Master postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: info: short_print: Slaves: [ postgres2 ]
Jul 09 09:16:35 [2681] postgres1 pengine: info: native_print: fencing-postgres1 (stonith:external/ec2): Started postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres2: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource AWSVIP: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:0: preferring current location (node=postgres1, weight=10)
Jul 09 09:16:35 [2681] postgres1 pengine: info: get_failcount_full: PGSQL:0 has failed 1 times on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 1 failures (max=1)
Jul 09 09:16:35 [2681] postgres1 pengine: info: get_failcount_full: PGSQL:1 has failed 1 times on postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 1 failures (max=1)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:1: preferring current location (node=postgres2, weight=10)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres1: preferring current location (node=postgres2, weight=10)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to fencing-postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to PGSQL:1
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: All nodes for resource PGSQL:0 are unavailable, unclean or shutting down (postgres1: 1, -1000000)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Could not allocate a node for PGSQL:0
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Processing PGSQL:0_stop_0
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Processing PGSQL:0_monitor_15000
Jul 09 09:16:35 [2681] postgres1 pengine: info: native_color: Resource PGSQL:0 cannot run anywhere
Jul 09 09:16:35 [2681] postgres1 pengine: debug: clone_color: Allocated 1 PGSQL-HA instances of a possible 2
Jul 09 09:16:35 [2681] postgres1 pengine: debug: master_color: PGSQL:1 master score: 1000
Jul 09 09:16:35 [2681] postgres1 pengine: info: master_color: Promoting PGSQL:1 (Slave postgres2)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: master_color: PGSQL:0 master score: 0
Jul 09 09:16:35 [2681] postgres1 pengine: info: master_color: PGSQL-HA: Promoted 1 instances of a possible 1 to master
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to AWSVIP
Jul 09 09:16:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to fencing-postgres1
Jul 09 09:16:35 [2681] postgres1 pengine: debug: master_create_actions: Creating actions for PGSQL-HA
Jul 09 09:16:35 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:1 on postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: info: RecurringOp: Cancelling action PGSQL:1_monitor_16000 (Slave vs. Master)
Jul 09 09:16:35 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:1 on postgres2
Jul 09 09:16:35 [2681] postgres1 pengine: info: RecurringOp: Cancelling action PGSQL:1_monitor_16000 (Slave vs. Master)
Jul 09 09:16:35 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres2 (Started postgres1)
Jul 09 09:16:35 [2681] postgres1 pengine: notice: LogActions: Move AWSVIP (Started postgres1 -> postgres2)
Jul 09 09:16:35 [2681] postgres1 pengine: notice: LogActions: Demote PGSQL:0 (Master -> Stopped postgres1)
Jul 09 09:16:35 [2681] postgres1 pengine: notice: LogActions: Promote PGSQL:1 (Slave -> Master postgres2)
Jul 09 09:16:35 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres1 (Started postgres2)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:16:35 [2681] postgres1 pengine: notice: process_pe_message: Calculated Transition 794: /var/lib/pacemaker/pengine/pe-input-21.bz2
Jul 09 09:16:35 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:16:35 [2682] postgres1 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:16:35 [2682] postgres1 crmd: debug: unpack_graph: Unpacked transition 794: 35 actions in 35 synapses
Jul 09 09:16:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 36 fired and confirmed
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=0, Pending=1, Fired=2, Skipped=0, Incomplete=33, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=46, reply=1, notify=0, exit=-121475024
Jul 09 09:16:35 [2679] postgres1 lrmd: info: log_execute: executing - rsc:PGSQL action:notify call_id:46
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=1, Pending=3, Fired=2, Skipped=0, Incomplete=31, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:35 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.4 2
Jul 09 09:16:35 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.5 (null)
Jul 09 09:16:35 [2677] postgres1 cib: info: cib_perform_op: -- /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_monitor_16000']
Jul 09 09:16:35 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=5
Jul 09 09:16:35 [2677] postgres1 cib: info: cib_process_request: Completed cib_delete operation for section status: OK (rc=0, origin=postgres2/crmd/20, version=0.117.5)
Jul 09 09:16:35 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_delete) diff: 0.117.4 -> 0.117.5 (S_TRANSITION_ENGINE)
Jul 09 09:16:35 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.5 to 0.117.4
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=2, Pending=2, Fired=0, Skipped=0, Incomplete=31, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [12755] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:35 [12755] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12755-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] connecting to client [12755]
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12755-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12755-24) state:2
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-12755-24-header
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12755-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] connecting to client [12755]
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12755-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12755-24) state:2
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:35 [12755] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-12755-24-header
Jul 09 09:16:35 [12755] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-12755-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-12755-24-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=12757 id=77c1de3e-6066-48eb-9938-dbfd4f6125ed
Jul 09 09:16:35 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-12757-13)
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [12757]
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:16:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:16:35 [12757] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:35 [12757] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op monitor for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12757-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-12757-13)
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-12757-13) state:2
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12757-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12757-13-header
Jul 09 09:16:35 [12757] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12757-13-header
Jul 09 09:16:35 [12757] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12757-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12757-13-header
Jul 09 09:16:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663795-8 from postgres2
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=3, Pending=1, Fired=0, Skipped=0, Incomplete=31, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:12748 - exited with rc=0
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:12748:stderr [ -- empty -- ]
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:12748:stdout [ /var/run/postgresql/:5432 - accepting connections ]
Jul 09 09:16:35 [2679] postgres1 lrmd: info: log_finished: finished - rsc:PGSQL action:notify call_id:46 pid:12748 exit-code:0 exec-time:259ms queue-time:0ms
Jul 09 09:16:35 [2682] postgres1 crmd: debug: create_operation_update: send_direct_ack: Updating resource PGSQL after notify op complete (interval=0)
Jul 09 09:16:35 [2682] postgres1 crmd: debug: send_direct_ack: ACK'ing resource op PGSQL_notify_0 from 52:794:0:ea56a968-bf94-4167-a81f-67a85176c75b: lrm_invoke-lrmd-1562663795-914
Jul 09 09:16:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663795-914 from postgres1
Jul 09 09:16:35 [2682] postgres1 crmd: notice: process_lrm_event: Operation PGSQL_notify_0: ok (node=postgres1, call=46, rc=0, cib-update=0, confirmed=true)
Jul 09 09:16:35 [2682] postgres1 crmd: debug: process_lrm_event: postgres1-PGSQL_notify_0:46 [ /var/run/postgresql/:5432 - accepting connections\n ]
Jul 09 09:16:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 37 fired and confirmed
Jul 09 09:16:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 34 fired and confirmed
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=4, Pending=0, Fired=2, Skipped=0, Incomplete=29, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [2682] postgres1 crmd: debug: stop_recurring_action_by_rsc: Cancelling op 43 for PGSQL (PGSQL:43)
Jul 09 09:16:35 [2682] postgres1 crmd: debug: cancel_op: Cancelling op 43 for PGSQL (PGSQL:43)
Jul 09 09:16:35 [2679] postgres1 lrmd: info: cancel_recurring_action: Cancelling ocf operation PGSQL_monitor_15000
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: log_finished: finished - rsc:PGSQL action:monitor call_id:43 exit-code:1 exec-time:0ms queue-time:0ms
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_cancel operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=0, reply=1, notify=0, exit=-121475024
Jul 09 09:16:35 [2682] postgres1 crmd: debug: cancel_op: Op 43 for PGSQL (PGSQL:43): cancelled
Jul 09 09:16:35 [2682] postgres1 crmd: debug: do_lrm_rsc_op: Stopped 0 recurring operations in preparation for PGSQL_demote_0
Jul 09 09:16:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=48, reply=1, notify=0, exit=-121475024
Jul 09 09:16:35 [2679] postgres1 lrmd: info: log_execute: executing - rsc:PGSQL action:demote call_id:48
Jul 09 09:16:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=6, Pending=1, Fired=1, Skipped=0, Incomplete=28, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:16:35 [2682] postgres1 crmd: debug: update_history_cache: Updating history for 'PGSQL' with monitor op
Jul 09 09:16:35 [12771] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:16:35 [12771] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12771-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] connecting to client [12771]
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-12771-24)
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12771-24) state:2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-12771-24-header
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-12771-24)
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] connecting to client [12771]
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 c
orosync debug [QB ] HUP conn (2637-12771-24)
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-12771-24) state:2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:16:35 [12771] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-12771-24-header
Jul 09 09:16:35 [12771] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-12771-24-header
Jul 09 09:16:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-12771-24-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=12773 id=dba09029-643e-498b-a4b9-08dc171448e8
Jul 09 09:16:35 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-12773-13)
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [12773]
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:16:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:16:35 [12773] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: determine_op_status: PGSQL_monitor_0 on postgres1 returned 'master' (8) instead of the expected value: 'not running' (7)
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource PGSQL:0 active in master mode on postgres1
Jul 09 09:16:35 [12773] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op monitor for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12773-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-12773-13)
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-12773-13) state:2
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12773-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-12773-13-header
Jul 09 09:16:35 [12773] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12773-13-header
Jul 09 09:16:35 [12773] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-12773-13-header
Jul 09 09:16:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-12773-13-header
Jul 09 09:16:40 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:16:52 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Jul 09 09:16:52 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.490000 (full: 0.49 0.25 0.17 1/272 13388)
Jul 09 09:16:52 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:17:22 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Jul 09 09:17:22 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.510000 (full: 0.51 0.28 0.18 1/273 14305)
Jul 09 09:17:22 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:17:52 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Jul 09 09:17:52 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.310000 (full: 0.31 0.25 0.18 1/273 14823)
Jul 09 09:17:52 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:18:22 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Jul 09 09:18:22 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.340000 (full: 0.34 0.26 0.18 1/274 15227)
Jul 09 09:18:22 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: child_kill_helper: Kill pid 12764's group
Jul 09 09:18:35 [2679] postgres1 lrmd: warning: child_timeout_callback: PGSQL_demote_0 process (PID 12764) timed out
Jul 09 09:18:35 [2679] postgres1 lrmd: warning: operation_finished: PGSQL_demote_0:12764 - timed out after 120000ms
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stderr [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ /var/run/postgresql/:5432 - accepting connections ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ waiting for server to shut down.... done ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ server stopped ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ /var/run/postgresql/:5432 - no response ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ /var/run/postgresql/:5432 - no response ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ waiting for server to start....2019-07-09 09:16:37 UTC LOG: redirecting log output to logging collector process ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ 2019-07-09 09:16:37 UTC HINT: Future log output will appear in directory "/var/log/postgresql". ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_demote_0:12764:stdout [ ..................................................................................................................... ]
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_finished: finished - rsc:PGSQL action:demote call_id:48 pid:12764 exit-code:1 exec-time:120001ms queue-time:0ms
Jul 09 09:18:35 [2682] postgres1 crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after demote op Timed Out (interval=0)
Jul 09 09:18:35 [2682] postgres1 crmd: notice: process_lrm_event: postgres1-PGSQL_demote_0:48 [ /var/run/postgresql/:5432 - accepting connections\nwaiting for server to shut down.... done\nserver stopped\n/var/run/postgresql/:5432 - no response\n/var/run/postgresql/:5432 - no response\nwaiting for server to start....2019-07-09 09:16:37 UTC LOG: redirecting log output to logging collector process\n2019-07-09 09:16:37 UTC HINT: Future log output will appear in directory "/var/log/postg
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_history_cache: Updating history for 'PGSQL' with demote op
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/955)
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.5 2
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.6 (null)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=6
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_last_failure_0']: @operation_key=PGSQL_demote_0, @operation=demote, @transition-key=11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=2:1;11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=48, @interval=0, @last-run=1562663795, @last-rc-change=1562663795, @exec-time=120001, @op-digest=d87a20560
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_last_0']: @operation_key=PGSQL_demote_0, @operation=demote, @crm-debug-origin=do_update_resource, @transition-key=11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=2:1;11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=48, @rc-code=1, @op-status=2, @last-run=1562663795, @last-rc-change=15626637
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/crmd/955, version=0.117.6)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.5 -> 0.117.6 (S_TRANSITION_ENGINE)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_abort_priority: Abort priority upgraded from 0 to 1
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_abort_priority: Abort action done superseded by restart: Event failed
Jul 09 09:18:35 [2682] postgres1 crmd: notice: abort_transition_graph: Transition aborted by PGSQL_demote_0 'modify' on postgres1: Event failed (magic=2:1;11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, cib=0.117.6, source=match_graph_event:381, 0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: fail-count-PGSQL=value++ for postgres1
Jul 09 09:18:35 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: last-failure-PGSQL=1562663915 for postgres1
Jul 09 09:18:35 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by PGSQL_demote_0 'modify' on postgres1: Event failed (magic=2:1;11:794:0:ea56a968-bf94-4167-a81f-67a85176c75b, cib=0.117.6, source=match_graph_event:381, 0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: fail-count-PGSQL=value++ for postgres1
Jul 09 09:18:35 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.6 to 0.117.5
Jul 09 09:18:35 [2682] postgres1 crmd: debug: attrd_update_delegate: Sent update: last-failure-PGSQL=1562663915 for postgres1
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 35 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=7, Pending=0, Fired=1, Skipped=0, Incomplete=27, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 38 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=8, Pending=0, Fired=1, Skipped=0, Incomplete=26, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting fail-count-PGSQL[postgres1] = 2 (writer)
Jul 09 09:18:35 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting last-failure-PGSQL[postgres1] = 1562663915 (writer)
Jul 09 09:18:35 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting fail-count-PGSQL[postgres1] = 2 (writer)
Jul 09 09:18:35 [2680] postgres1 attrd: debug: attrd_client_update: Broadcasting last-failure-PGSQL[postgres1] = 1562663915 (writer)
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=49, reply=1, notify=0, exit=-121475024
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attribute: Update: postgres1[fail-count-PGSQL]=2 (2 2 2 postgres1)
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_execute: executing - rsc:PGSQL action:notify call_id:49
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attribute: Update: postgres1[last-failure-PGSQL]=1562663915 (2 2 2 postgres1)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/27)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/attrd/28)
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.6 2
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.7 (null)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=7
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']/nvpair[@id='status-2-fail-count-PGSQL']: @value=2
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=9, Pending=2, Fired=2, Skipped=0, Incomplete=24, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/attrd/27, version=0.117.7)
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.7 2
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.8 (null)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=8
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']/nvpair[@id='status-2-last-failure-PGSQL']: @value=1562663915
Jul 09 09:18:35 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.7 to 0.117.6
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/attrd/28, version=0.117.8)
Jul 09 09:18:35 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.8 to 0.117.7
Jul 09 09:18:35 [2680] postgres1 attrd: info: attrd_cib_callback: Update 27 for fail-count-PGSQL: OK (0)
Jul 09 09:18:35 [2680] postgres1 attrd: info: attrd_cib_callback: Update 27 for fail-count-PGSQL[postgres1]=2: OK (0)
Jul 09 09:18:35 [2680] postgres1 attrd: info: attrd_cib_callback: Update 28 for last-failure-PGSQL: OK (0)
Jul 09 09:18:35 [2680] postgres1 attrd: info: attrd_cib_callback: Update 28 for last-failure-PGSQL[postgres1]=1562663915: OK (0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.6 -> 0.117.7 (S_TRANSITION_ENGINE)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_abort_priority: Abort priority upgraded from 1 to 1000000
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_abort_priority: 'Event failed' abort superseded by Transient attribute change
Jul 09 09:18:35 [2682] postgres1 crmd: notice: abort_transition_graph: Transition aborted by status-2-fail-count-PGSQL, fail-count-PGSQL=2: Transient attribute change (modify cib=0.117.7, source=abort_unless_down:329, path=/cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']/nvpair[@id='status-2-fail-count-PGSQL'], 0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.7 -> 0.117.8 (S_TRANSITION_ENGINE)
Jul 09 09:18:35 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by status-2-last-failure-PGSQL, last-failure-PGSQL=1562663915: Transient attribute change (modify cib=0.117.8, source=abort_unless_down:329, path=/cib/status/node_state[@id='2']/transient_attributes[@id='2']/instance_attributes[@id='status-2']/nvpair[@id='status-2-last-failure-PGSQL'], 0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=9, Pending=2, Fired=0, Skipped=0, Incomplete=24, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [15362] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:18:35 [15362] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15362-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15362]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15362-24)
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15362-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-15362-24-header
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15362-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15362]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-15362-24-header
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15362-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15362-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15362] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-15362-24-header
Jul 09 09:18:35 [15362] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-15362-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-15362-24-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=15364 id=da165871-8829-4032-9270-ef0a2a0e2b31
Jul 09 09:18:35 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-15364-13)
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [15364]
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:18:35 [15364] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:18:35 [15364] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15364] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15364] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15364] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15364-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-15364-13)
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15364-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-15364-13) state:2
Jul 09 09:18:35 [15364] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15364-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15364-13-header
Jul 09 09:18:35 [15364] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15364-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15364-13-header
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663915-9 from postgres2
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=10, Pending=1, Fired=0, Skipped=0, Incomplete=24, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15355 - exited with rc=0
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15355:stderr [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15355:stdout [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_finished: finished - rsc:PGSQL action:notify call_id:49 pid:15355 exit-code:0 exec-time:69ms queue-time:0ms
Jul 09 09:18:35 [2682] postgres1 crmd: debug: create_operation_update: send_direct_ack: Updating resource PGSQL after notify op complete (interval=0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: send_direct_ack: ACK'ing resource op PGSQL_notify_0 from 53:794:0:ea56a968-bf94-4167-a81f-67a85176c75b: lrm_invoke-lrmd-1562663915-918
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663915-918 from postgres1
Jul 09 09:18:35 [2682] postgres1 crmd: notice: process_lrm_event: Operation PGSQL_notify_0: ok (node=postgres1, call=49, rc=0, cib-update=0, confirmed=true)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 39 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 24 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 794 (Complete=11, Pending=0, Fired=2, Skipped=0, Incomplete=22, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: notice: run_graph: Transition 794 (Complete=13, Pending=0, Fired=0, Skipped=3, Incomplete=22, Source=/var/lib/pacemaker/pengine/pe-input-21.bz2): Stopped
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_graph_trigger: Transition 794 is now complete
Jul 09 09:18:35 [2682] postgres1 crmd: debug: notify_crmd: Processing transition completion in state S_TRANSITION_ENGINE
Jul 09 09:18:35 [2682] postgres1 crmd: debug: notify_crmd: Transition 794 status: restart - Transient attribute change
Jul 09 09:18:35 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:35 [2682] postgres1 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:35 [2682] postgres1 crmd: debug: do_state_transition: All 2 cluster nodes are eligible to run resources.
Jul 09 09:18:35 [2682] postgres1 crmd: debug: do_pe_invoke: Query 956: Requesting the current CIB: S_POLICY_ENGINE
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [2682] postgres1 crmd: debug: do_pe_invoke_callback: Invoking the PE: query=956, ref=pe_calc-dc-1562663915-919, seq=76, quorate=1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: Stop all active resources: false
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: Default stickiness: 0
Jul 09 09:18:35 [2681] postgres1 pengine: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:18:35 [2681] postgres1 pengine: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_online_status: Node postgres1 is online
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_online_status: Node postgres2 is online
Jul 09 09:18:35 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:18:35 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:18:35 [2681] postgres1 pengine: info: native_print: fencing-postgres2 (stonith:external/ec2): Started postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: info: native_print: AWSVIP (ocf::heartbeat:awsvip): Started postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: info: clone_print: Master/Slave Set: PGSQL-HA [PGSQL]
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:0 active on postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: info: native_print: PGSQL (ocf::heartbeat:pgsqlms): FAILED postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:1 active on postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: info: short_print: Slaves: [ postgres2 ]
Jul 09 09:18:35 [2681] postgres1 pengine: info: native_print: fencing-postgres1 (stonith:external/ec2): Started postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres2: preferring current location (node=postgres1, weight=10)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource AWSVIP: preferring current location (node=postgres1, weight=10)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:0: preferring current location (node=postgres1, weight=10)
Jul 09 09:18:35 [2681] postgres1 pengine: info: get_failcount_full: PGSQL:0 has failed 2 times on postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 2 failures (max=1)
Jul 09 09:18:35 [2681] postgres1 pengine: info: get_failcount_full: PGSQL:1 has failed 2 times on postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 2 failures (max=1)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:1: preferring current location (node=postgres2, weight=10)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres1: preferring current location (node=postgres2, weight=10)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to fencing-postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to PGSQL:1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: All nodes for resource PGSQL:0 are unavailable, unclean or shutting down (postgres1: 1, -1000000)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Could not allocate a node for PGSQL:0
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Processing PGSQL:0_stop_0
Jul 09 09:18:35 [2681] postgres1 pengine: info: native_color: Resource PGSQL:0 cannot run anywhere
Jul 09 09:18:35 [2681] postgres1 pengine: debug: clone_color: Allocated 1 PGSQL-HA instances of a possible 2
Jul 09 09:18:35 [2681] postgres1 pengine: debug: master_color: PGSQL:1 master score: 1000
Jul 09 09:18:35 [2681] postgres1 pengine: info: master_color: Promoting PGSQL:1 (Slave postgres2)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: master_color: PGSQL:0 master score: 0
Jul 09 09:18:35 [2681] postgres1 pengine: info: master_color: PGSQL-HA: Promoted 1 instances of a possible 1 to master
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to AWSVIP
Jul 09 09:18:35 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to fencing-postgres1
Jul 09 09:18:35 [2681] postgres1 pengine: debug: master_create_actions: Creating actions for PGSQL-HA
Jul 09 09:18:35 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:1 on postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: info: RecurringOp: Start recurring monitor (15s) for PGSQL:1 on postgres2
Jul 09 09:18:35 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres2 (Started postgres1)
Jul 09 09:18:35 [2681] postgres1 pengine: notice: LogActions: Stop AWSVIP (Started postgres1 - blocked)
Jul 09 09:18:35 [2681] postgres1 pengine: notice: LogActions: Stop PGSQL:0 (postgres1)
Jul 09 09:18:35 [2681] postgres1 pengine: notice: LogActions: Promote PGSQL:1 (Slave -> Master postgres2)
Jul 09 09:18:35 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres1 (Started postgres2)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:0 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: debug: action2xml: Using anonymous clone name PGSQL for PGSQL:1 (aka. PGSQL)
Jul 09 09:18:35 [2681] postgres1 pengine: notice: process_pe_message: Calculated Transition 795: /var/lib/pacemaker/pengine/pe-input-22.bz2
Jul 09 09:18:35 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:18:35 [2682] postgres1 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:18:35 [2682] postgres1 crmd: debug: unpack_graph: Unpacked transition 795: 20 actions in 20 synapses
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 21 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=0, Pending=0, Fired=1, Skipped=0, Incomplete=19, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=50, reply=1, notify=0, exit=-121475024
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_execute: executing - rsc:PGSQL action:notify call_id:50
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=1, Pending=2, Fired=2, Skipped=0, Incomplete=17, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [15374] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:18:35 [15374] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15374-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15374]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15374-24)
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15374-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-15374-24-header
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15374-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15374]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15374-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15374-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-15374-24-header
Jul 09 09:18:35 [15374] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-15374-24-header
Jul 09 09:18:35 [15374] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-15374-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-15374-24-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=15376 id=132f5be5-0ab5-4777-9c70-4a1e62b6ea63
Jul 09 09:18:35 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-15376-13)
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [15376]
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:18:35 [15376] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:18:35 [15376] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15376] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15376] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15376] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15376-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-15376-13)
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-15376-13) state:2
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15376-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:18:35 [15376] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15376-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15376-13-header
Jul 09 09:18:35 [15376] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15376-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15376-13-header
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663915-10 from postgres2
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=17, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15367 - exited with rc=0
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15367:stderr [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_notify_0:15367:stdout [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_finished: finished - rsc:PGSQL action:notify call_id:50 pid:15367 exit-code:0 exec-time:68ms queue-time:0ms
Jul 09 09:18:35 [2682] postgres1 crmd: debug: create_operation_update: send_direct_ack: Updating resource PGSQL after notify op complete (interval=0)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: send_direct_ack: ACK'ing resource op PGSQL_notify_0 from 44:795:0:ea56a968-bf94-4167-a81f-67a85176c75b: lrm_invoke-lrmd-1562663915-922
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663915-922 from postgres1
Jul 09 09:18:35 [2682] postgres1 crmd: notice: process_lrm_event: Operation PGSQL_notify_0: ok (node=postgres1, call=50, rc=0, cib-update=0, confirmed=true)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 22 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 19 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=3, Pending=0, Fired=2, Skipped=0, Incomplete=15, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: do_lrm_rsc_op: Stopped 0 recurring operations in preparation for PGSQL_stop_0
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=51, reply=1, notify=0, exit=-121475024
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_execute: executing - rsc:PGSQL action:stop call_id:51
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=5, Pending=1, Fired=1, Skipped=0, Incomplete=14, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [15388] postgres1 crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Jul 09 09:18:35 [15388] postgres1 crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15388-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15388]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-2637-15388-24-header
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15388-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15388-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-2637-15388-24-header
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: get_local_nodeid: Local nodeid is 2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] IPC credentials authenticated (2637-15388-24)
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] connecting to client [15388]
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] HUP conn (2637-15388-24)
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] qb_ipcs_disconnect(2637-15388-24) state:2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Jul 09 09:18:35 [15388] postgres1 crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-2637-15388-24-header
Jul 09 09:18:35 [15388] postgres1 crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-2637-15388-24-header
Jul 09 09:18:35 [2637] postgres1 corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-2637-15388-24-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_new: Connecting 0x55c11034a950 for uid=0 gid=0 pid=15390 id=3f3733f6-efdf-4702-8c32-b69e85268a2a
Jul 09 09:18:35 [2677] postgres1 cib: debug: handle_new_connection: IPC credentials authenticated (2677-15390-13)
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_shm_connect: connecting to client [15390]
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: Stop all active resources: false
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: Default stickiness: 0
Jul 09 09:18:35 [15390] postgres1 crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_online_status: Node postgres1 is online
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_online_status: Node postgres2 is online
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:18:35 [15390] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15390] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15390] postgres1 crm_resource: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:35 [15390] postgres1 crm_resource: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:1
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15390-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (2677-15390-13)
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(2677-15390-13) state:2
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15390-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: crm_client_destroy: Destroying 0 events
Jul 09 09:18:35 [15390] postgres1 crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15390-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-2677-15390-13-header
Jul 09 09:18:35 [15390] postgres1 crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-2677-15390-13-header
Jul 09 09:18:35 [2677] postgres1 cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-2677-15390-13-header
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_stop_0:15381 - exited with rc=0
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_stop_0:15381:stderr [ -- empty -- ]
Jul 09 09:18:35 [2679] postgres1 lrmd: debug: operation_finished: PGSQL_stop_0:15381:stdout [ /var/run/postgresql/:5432 - no response ]
Jul 09 09:18:35 [2679] postgres1 lrmd: info: log_finished: finished - rsc:PGSQL action:stop call_id:51 pid:15381 exit-code:0 exec-time:246ms queue-time:0ms
Jul 09 09:18:35 [2682] postgres1 crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after stop op complete (interval=0)
Jul 09 09:18:35 [2682] postgres1 crmd: notice: process_lrm_event: Operation PGSQL_stop_0: ok (node=postgres1, call=51, rc=0, cib-update=957, confirmed=true)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_lrm_event: postgres1-PGSQL_stop_0:51 [ /var/run/postgresql/:5432 - no response\n ]
Jul 09 09:18:35 [2682] postgres1 crmd: debug: update_history_cache: Updating history for 'PGSQL' with stop op
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/957)
Jul 09 09:18:35 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.8 2
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.9 (null)
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=9
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_last_0']: @operation_key=PGSQL_stop_0, @operation=stop, @transition-key=2:795:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=0:0;2:795:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=51, @rc-code=0, @op-status=0, @last-run=1562663915, @last-rc-change=1562663915, @exec-time=246
Jul 09 09:18:35 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/crmd/957, version=0.117.9)
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.8 -> 0.117.9 (S_TRANSITION_ENGINE)
Jul 09 09:18:35 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.9 to 0.117.8
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 20 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=6, Pending=0, Fired=1, Skipped=0, Incomplete=13, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 23 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=7, Pending=0, Fired=1, Skipped=0, Incomplete=12, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=8, Pending=1, Fired=1, Skipped=0, Incomplete=11, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663915-11 from postgres2
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 24 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=9, Pending=0, Fired=1, Skipped=0, Incomplete=10, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 27 fired and confirmed
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=10, Pending=0, Fired=1, Skipped=0, Incomplete=9, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=11, Pending=1, Fired=1, Skipped=0, Incomplete=8, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute shutdown
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute terminate
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute lsn_location-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute lsn_location-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute terminate
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute recover_master-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute shutdown
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute lsn_location-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute terminate
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute recover_master-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute nodes-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute shutdown
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute lsn_location-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute fail-count-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute terminate
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute recover_master-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute last-failure-fencing-postgres1
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute nodes-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute cancel_switchover-PGSQL
Jul 09 09:18:35 [2680] postgres1 attrd: debug: write_attributes: Skipping unchanged attribute shutdown
Jul 09 09:18:36 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663916-12 from postgres2
Jul 09 09:18:36 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 28 fired and confirmed
Jul 09 09:18:36 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 25 fired and confirmed
Jul 09 09:18:36 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=12, Pending=0, Fired=2, Skipped=0, Incomplete=6, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:36 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=14, Pending=1, Fired=1, Skipped=0, Incomplete=5, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:37 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:37 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.9 2
Jul 09 09:18:37 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.117.10 (null)
Jul 09 09:18:37 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=10
Jul 09 09:18:37 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='PGSQL']/lrm_rsc_op[@id='PGSQL_last_0']: @operation_key=PGSQL_promote_0, @operation=promote, @transition-key=11:795:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=0:0;11:795:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=30, @last-run=1562663916, @last-rc-change=1562663916, @exec-time=1830
Jul 09 09:18:37 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres2/crmd/21, version=0.117.10)
Jul 09 09:18:37 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.117.10 to 0.117.9
Jul 09 09:18:37 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.9 -> 0.117.10 (S_TRANSITION_ENGINE)
Jul 09 09:18:37 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 26 fired and confirmed
Jul 09 09:18:37 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=15, Pending=0, Fired=1, Skipped=0, Incomplete=4, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:37 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 29 fired and confirmed
Jul 09 09:18:37 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=16, Pending=0, Fired=1, Skipped=0, Incomplete=3, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:37 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=17, Pending=1, Fired=1, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:37 [2682] postgres1 crmd: debug: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1562663917-13 from postgres2
Jul 09 09:18:37 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 30 fired and confirmed
Jul 09 09:18:37 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=18, Pending=0, Fired=1, Skipped=0, Incomplete=1, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:37 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=19, Pending=1, Fired=1, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.117.10 2
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.118.0 9ab6152b81410093e8be27ab1ee041ae
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: + /cib: @epoch=118, @num_updates=0
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: + /cib/configuration/nodes/node[@id='2']/instance_attributes[@id='nodes-2']/nvpair[@id='nodes-2-master-PGSQL']: @value=-1000
Jul 09 09:18:38 [2677] postgres1 cib: debug: activateCibXml: Triggering CIB write for cib_modify op
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.118.0)
Jul 09 09:18:38 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.118.0 to 0.117.10
Jul 09 09:18:38 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.117.10 -> 0.118.0 (S_TRANSITION_ENGINE)
Jul 09 09:18:38 [2682] postgres1 crmd: debug: update_abort_priority: Abort priority upgraded from 0 to 1000000
Jul 09 09:18:38 [2682] postgres1 crmd: debug: update_abort_priority: Abort action done superseded by restart: Non-status change
Jul 09 09:18:38 [2682] postgres1 crmd: notice: abort_transition_graph: Transition aborted by nodes-2-master-PGSQL, master-PGSQL=-1000: Non-status change (modify cib=0.118.0, source=te_update_diff:436, path=/cib/configuration/nodes/node[@id='2']/instance_attributes[@id='nodes-2']/nvpair[@id='nodes-2-master-PGSQL'], 0)
Jul 09 09:18:38 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=19, Pending=1, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-40.raw
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Writing CIB to disk
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_write_with_digest: Wrote version 0.118.0 of the CIB to disk (digest: 2a018902486fe93547748fbb6ea6744c)
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Wrote digest 2a018902486fe93547748fbb6ea6744c to disk
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.Yz5bvB (digest: /var/lib/pacemaker/cib/cib.CPS6yC)
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Activating /var/lib/pacemaker/cib/cib.Yz5bvB
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.118.0 2
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.119.0 (null)
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: + /cib: @epoch=119
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: + /cib/configuration/nodes/node[@id='1']/instance_attributes[@id='nodes-1']/nvpair[@id='nodes-1-master-PGSQL']: @value=1001
Jul 09 09:18:38 [2677] postgres1 cib: debug: activateCibXml: Triggering CIB write for cib_modify op
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.0)
Jul 09 09:18:38 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.119.0 to 0.118.0
Jul 09 09:18:38 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.118.0 -> 0.119.0 (S_TRANSITION_ENGINE)
Jul 09 09:18:38 [2682] postgres1 crmd: info: abort_transition_graph: Transition aborted by nodes-1-master-PGSQL, master-PGSQL=1001: Non-status change (modify cib=0.119.0, source=te_update_diff:436, path=/cib/configuration/nodes/node[@id='1']/instance_attributes[@id='nodes-1']/nvpair[@id='nodes-1-master-PGSQL'], 0)
Jul 09 09:18:38 [2682] postgres1 crmd: debug: run_graph: Transition 795 (Complete=19, Pending=1, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): In-progress
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-41.raw
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Writing CIB to disk
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_write_with_digest: Wrote version 0.119.0 of the CIB to disk (digest: cc8bb59349226ee29efe9a3898fa9bf0)
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Wrote digest cc8bb59349226ee29efe9a3898fa9bf0 to disk
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.DcFbSH (digest: /var/lib/pacemaker/cib/cib.0vYj8I)
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_file_write_with_digest: Activating /var/lib/pacemaker/cib/cib.DcFbSH
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.119.0 2
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.119.1 (null)
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=1
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='PGSQL']: <lrm_rsc_op id="PGSQL_monitor_15000" operation_key="PGSQL_monitor_15000" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="12:795:8:ea56a968-bf94-4167-a81f-67a85176c75b" transition-magic="0:8;12:795:8:ea56a968-bf94-4167-a81f-67a85176c75b" on_node="postgres2" call-id="32" rc-code="8" op-s
Jul 09 09:18:38 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres2/crmd/22, version=0.119.1)
Jul 09 09:18:38 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.119.0 -> 0.119.1 (S_TRANSITION_ENGINE)
Jul 09 09:18:38 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.119.1 to 0.119.0
Jul 09 09:18:38 [2682] postgres1 crmd: notice: run_graph: Transition 795 (Complete=20, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-22.bz2): Complete
Jul 09 09:18:38 [2682] postgres1 crmd: debug: te_graph_trigger: Transition 795 is now complete
Jul 09 09:18:38 [2682] postgres1 crmd: debug: notify_crmd: Processing transition completion in state S_TRANSITION_ENGINE
Jul 09 09:18:38 [2682] postgres1 crmd: debug: notify_crmd: Transition 795 status: restart - Non-status change
Jul 09 09:18:38 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:38 [2682] postgres1 crmd: info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:38 [2682] postgres1 crmd: debug: do_state_transition: All 2 cluster nodes are eligible to run resources.
Jul 09 09:18:38 [2682] postgres1 crmd: debug: do_pe_invoke: Query 958: Requesting the current CIB: S_POLICY_ENGINE
Jul 09 09:18:38 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:38 [2682] postgres1 crmd: debug: do_pe_invoke_callback: Invoking the PE: query=958, ref=pe_calc-dc-1562663918-929, seq=76, quorate=1
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: STONITH timeout: 60000
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: STONITH of failed nodes is enabled
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: Stop all active resources: false
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: Default stickiness: 0
Jul 09 09:18:38 [2681] postgres1 pengine: notice: unpack_config: On loss of CCM Quorum: Ignore
Jul 09 09:18:38 [2681] postgres1 pengine: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres1 is active
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_online_status: Node postgres1 is online
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_online_status_fencing: Node postgres2 is active
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_online_status: Node postgres2 is online
Jul 09 09:18:38 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: debug: determine_op_status: AWSVIP_monitor_0 on postgres1 returned 'ok' (0) instead of the expected value: 'not running' (7)
Jul 09 09:18:38 [2681] postgres1 pengine: info: determine_op_status: Operation monitor found resource AWSVIP active on postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres1 to PGSQL:0
Jul 09 09:18:38 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Processing failed op demote for PGSQL:0 on postgres1: unknown error (1)
Jul 09 09:18:38 [2681] postgres1 pengine: warning: unpack_rsc_op_failure: Forcing PGSQL:0 to stop after a failed demote action
Jul 09 09:18:38 [2681] postgres1 pengine: debug: find_anonymous_clone: Internally renamed PGSQL on postgres2 to PGSQL:0
Jul 09 09:18:38 [2681] postgres1 pengine: info: native_print: fencing-postgres2 (stonith:external/ec2): Started postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: info: native_print: AWSVIP (ocf::heartbeat:awsvip): Started postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: info: clone_print: Master/Slave Set: PGSQL-HA [PGSQL]
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:0 active on postgres2
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_active: Resource PGSQL:0 active on postgres2
Jul 09 09:18:38 [2681] postgres1 pengine: info: short_print: Masters: [ postgres2 ]
Jul 09 09:18:38 [2681] postgres1 pengine: info: short_print: Stopped: [ postgres1 ]
Jul 09 09:18:38 [2681] postgres1 pengine: info: native_print: fencing-postgres1 (stonith:external/ec2): Started postgres2
Jul 09 09:18:38 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres2: preferring current location (node=postgres1, weight=10)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource AWSVIP: preferring current location (node=postgres1, weight=10)
Jul 09 09:18:38 [2681] postgres1 pengine: info: get_failcount_full: PGSQL:0 has failed 2 times on postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 2 failures (max=1)
Jul 09 09:18:38 [2681] postgres1 pengine: info: get_failcount_full: PGSQL-HA has failed 2 times on postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: warning: common_apply_stickiness: Forcing PGSQL-HA away from postgres1 after 2 failures (max=1)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource PGSQL:0: preferring current location (node=postgres2, weight=10)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: common_apply_stickiness: Resource fencing-postgres1: preferring current location (node=postgres2, weight=10)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres1 to fencing-postgres2
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to PGSQL:0
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: All nodes for resource PGSQL:1 are unavailable, unclean or shutting down (postgres1: 1, -1000000)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: Could not allocate a node for PGSQL:1
Jul 09 09:18:38 [2681] postgres1 pengine: info: native_color: Resource PGSQL:1 cannot run anywhere
Jul 09 09:18:38 [2681] postgres1 pengine: debug: clone_color: Allocated 1 PGSQL-HA instances of a possible 2
Jul 09 09:18:38 [2681] postgres1 pengine: debug: master_color: PGSQL:0 master score: 1001
Jul 09 09:18:38 [2681] postgres1 pengine: info: master_color: Promoting PGSQL:0 (Master postgres2)
Jul 09 09:18:38 [2681] postgres1 pengine: debug: master_color: PGSQL:1 master score: 0
Jul 09 09:18:38 [2681] postgres1 pengine: info: master_color: PGSQL-HA: Promoted 1 instances of a possible 1 to master
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to AWSVIP
Jul 09 09:18:38 [2681] postgres1 pengine: debug: native_assign_node: Assigning postgres2 to fencing-postgres1
Jul 09 09:18:38 [2681] postgres1 pengine: debug: master_create_actions: Creating actions for PGSQL-HA
Jul 09 09:18:38 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres2 (Started postgres1)
Jul 09 09:18:38 [2681] postgres1 pengine: notice: LogActions: Move AWSVIP (Started postgres1 -> postgres2)
Jul 09 09:18:38 [2681] postgres1 pengine: info: LogActions: Leave PGSQL:0 (Master postgres2)
Jul 09 09:18:38 [2681] postgres1 pengine: info: LogActions: Leave PGSQL:1 (Stopped)
Jul 09 09:18:38 [2681] postgres1 pengine: info: LogActions: Leave fencing-postgres1 (Started postgres2)
Jul 09 09:18:38 [2681] postgres1 pengine: notice: process_pe_message: Calculated Transition 796: /var/lib/pacemaker/pengine/pe-input-23.bz2
Jul 09 09:18:38 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:18:38 [2682] postgres1 crmd: info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ]
Jul 09 09:18:38 [2682] postgres1 crmd: debug: unpack_graph: Unpacked transition 796: 3 actions in 3 synapses
Jul 09 09:18:38 [2682] postgres1 crmd: debug: do_lrm_rsc_op: Stopped 0 recurring operations in preparation for AWSVIP_stop_0
Jul 09 09:18:38 [2679] postgres1 lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 7872e7fd-95e5-482d-9e52-479f01b7ba6f: rc=52, reply=1, notify=0, exit=-121475024
Jul 09 09:18:38 [2679] postgres1 lrmd: info: log_execute: executing - rsc:AWSVIP action:stop call_id:52
Jul 09 09:18:38 [2682] postgres1 crmd: debug: run_graph: Transition 796 (Complete=0, Pending=1, Fired=1, Skipped=0, Incomplete=2, Source=/var/lib/pacemaker/pengine/pe-input-23.bz2): In-progress
Jul 09 09:18:43 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:44 [2679] postgres1 lrmd: debug: operation_finished: AWSVIP_stop_0:15396 - exited with rc=0
Jul 09 09:18:44 [2679] postgres1 lrmd: debug: operation_finished: AWSVIP_stop_0:15396:stderr [ -- empty -- ]
Jul 09 09:18:44 [2679] postgres1 lrmd: debug: operation_finished: AWSVIP_stop_0:15396:stdout [ -- empty -- ]
Jul 09 09:18:44 [2679] postgres1 lrmd: info: log_finished: finished - rsc:AWSVIP action:stop call_id:52 pid:15396 exit-code:0 exec-time:6417ms queue-time:0ms
Jul 09 09:18:44 [2682] postgres1 crmd: debug: create_operation_update: do_update_resource: Updating resource AWSVIP after stop op complete (interval=0)
Jul 09 09:18:44 [2682] postgres1 crmd: notice: process_lrm_event: Operation AWSVIP_stop_0: ok (node=postgres1, call=52, rc=0, cib-update=959, confirmed=true)
Jul 09 09:18:44 [2682] postgres1 crmd: debug: update_history_cache: Updating history for 'AWSVIP' with stop op
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/959)
Jul 09 09:18:44 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.119.1 2
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.119.2 (null)
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=2
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_resource[@id='AWSVIP']/lrm_rsc_op[@id='AWSVIP_last_0']: @operation_key=AWSVIP_stop_0, @operation=stop, @crm-debug-origin=do_update_resource, @transition-key=7:796:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=0:0;7:796:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=52, @last-run=1562663918, @last-rc-change=1562663918, @exec-time=6417
Jul 09 09:18:44 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres1/crmd/959, version=0.119.2)
Jul 09 09:18:44 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.119.1 -> 0.119.2 (S_TRANSITION_ENGINE)
Jul 09 09:18:44 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.119.2 to 0.119.1
Jul 09 09:18:44 [2682] postgres1 crmd: debug: te_pseudo_action: Pseudo action 4 fired and confirmed
Jul 09 09:18:44 [2682] postgres1 crmd: debug: run_graph: Transition 796 (Complete=1, Pending=1, Fired=2, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-23.bz2): In-progress
Jul 09 09:18:44 [2682] postgres1 crmd: debug: run_graph: Transition 796 (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-23.bz2): In-progress
Jul 09 09:18:49 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:51 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:51 [2677] postgres1 cib: info: cib_perform_op: Diff: --- 0.119.2 2
Jul 09 09:18:51 [2677] postgres1 cib: info: cib_perform_op: Diff: +++ 0.119.3 (null)
Jul 09 09:18:51 [2677] postgres1 cib: info: cib_perform_op: + /cib: @num_updates=3
Jul 09 09:18:51 [2677] postgres1 cib: info: cib_perform_op: + /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources/lrm_resource[@id='AWSVIP']/lrm_rsc_op[@id='AWSVIP_last_0']: @operation_key=AWSVIP_start_0, @operation=start, @transition-key=8:796:0:ea56a968-bf94-4167-a81f-67a85176c75b, @transition-magic=0:0;8:796:0:ea56a968-bf94-4167-a81f-67a85176c75b, @call-id=33, @rc-code=0, @last-run=1562663924, @last-rc-change=1562663924, @exec-time=6930
Jul 09 09:18:51 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=postgres2/crmd/23, version=0.119.3)
Jul 09 09:18:51 [2682] postgres1 crmd: debug: te_update_diff: Processing (cib_modify) diff: 0.119.2 -> 0.119.3 (S_TRANSITION_ENGINE)
Jul 09 09:18:51 [2682] postgres1 crmd: notice: run_graph: Transition 796 (Complete=3, Pending=0, Fired=0, Skipped=0, Incomplete=0, Source=/var/lib/pacemaker/pengine/pe-input-23.bz2): Complete
Jul 09 09:18:51 [2682] postgres1 crmd: debug: te_graph_trigger: Transition 796 is now complete
Jul 09 09:18:51 [2678] postgres1 stonith-ng: debug: xml_patch_version_check: Can apply patch 0.119.3 to 0.119.2
Jul 09 09:18:51 [2682] postgres1 crmd: debug: notify_crmd: Processing transition completion in state S_TRANSITION_ENGINE
Jul 09 09:18:51 [2682] postgres1 crmd: debug: notify_crmd: Transition 796 status: done - <null>
Jul 09 09:18:51 [2682] postgres1 crmd: debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:51 [2682] postgres1 crmd: info: do_log: FSA: Input I_TE_SUCCESS from notify_crmd() received in state S_TRANSITION_ENGINE
Jul 09 09:18:51 [2682] postgres1 crmd: notice: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ]
Jul 09 09:18:51 [2682] postgres1 crmd: debug: do_state_transition: Starting PEngine Recheck Timer
Jul 09 09:18:51 [2682] postgres1 crmd: debug: crm_timer_start: Started PEngine Recheck Timer (I_PE_CALC:900000ms), src=1826
Jul 09 09:18:52 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Jul 09 09:18:52 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.200000 (full: 0.20 0.23 0.18 1/267 15444)
Jul 09 09:18:52 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:18:53 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:18:53 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.3)
Jul 09 09:18:58 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:09 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:09 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.3)
Jul 09 09:19:14 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:22 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Jul 09 09:19:22 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.120000 (full: 0.12 0.21 0.17 1/268 15460)
Jul 09 09:19:22 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:19:24 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:24 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.3)
Jul 09 09:19:29 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:39 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:39 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.3)
Jul 09 09:19:44 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:52 [2682] postgres1 crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Jul 09 09:19:52 [2682] postgres1 crmd: debug: throttle_load_avg: Current load is 0.070000 (full: 0.07 0.19 0.16 1/268 15460)
Jul 09 09:19:52 [2682] postgres1 crmd: debug: throttle_io_load: Current IO load is 0.000000
Jul 09 09:19:55 [2677] postgres1 cib: debug: cib_acl_enabled: CIB ACL is disabled
Jul 09 09:19:55 [2677] postgres1 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=postgres2/crm_attribute/4, version=0.119.3)
More information about the Users
mailing list