[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