[ClusterLabs] Fwd: Postgres pacemaker cluster failure
Danka Ivanović
danka.ivanovic at gmail.com
Tue Apr 30 11:28:44 EDT 2019
Hi, I tried new clean config with upgraded postgres and corosync and
pacemaker packages.
dpkg -l | grep postgres
ii pgdg-keyring 2018.2
all keyring for apt.*postgres*ql.org
hi *postgres*ql-9.6 9.6.12-1.pgdg16.04+1
amd64 object-relational SQL database, version 9.6 server
ii *postgres*ql-client-9.6 9.6.12-1.pgdg16.04+1
amd64 front-end programs for PostgreSQL 9.6
ii *postgres*ql-client-common 197.pgdg16.04+1
all manager for multiple PostgreSQL client versions
ii *postgres*ql-common 197.pgdg16.04+1
all PostgreSQL database-cluster manager
ii *postgres*ql-contrib-9.6 9.6.12-1.pgdg16.04+1
amd64 additional facilities for PostgreSQL
dpkg -l | grep corosync
ii *corosync* 2.3.5-3ubuntu2.1
amd64 cluster engine daemon and utilities
ii lib*corosync*-common4:amd64 2.3.5-3ubuntu2.1
amd64 cluster engine common library
dpkg -l | grep pacemaker
ii crmsh 2.2.0-1
amd64 CRM shell for the *pacemaker* cluster manager
ii *pacemaker* 1.1.14-2ubuntu1.6
amd64 cluster resource manager
ii *pacemaker*-cli-utils 1.1.14-2ubuntu1.6
amd64 cluster resource manager command line utilities
ii *pacemaker*-common 1.1.14-2ubuntu1.6
all cluster resource manager common files
rc *pacemaker*-remote 1.1.14-2ubuntu1.6
amd64 cluster resource manager proxy daemon for remote nodes
ii *pacemaker*-resource-agents 1.1.14-2ubuntu1.6
all cluster resource manager general resource agents
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 16.04.5 LTS
Release: 16.04
Codename: xenial
crm configure show
node 1: master
node 2: secondary
primitive AWSVIP awsvip \
params secondary_private_ip=10.x.x.x api_delay=5
primitive PGSQL pgsqlms \
params pgdata="/var/lib/postgresql/9.6/main"
bindir="/usr/lib/postgresql/9.6/bin" pghost="/var/run/postgresql/"
recovery_template="/etc/postgresql/9.6/main/recovery.conf.pcmk"
start_opts="-c config_file=/etc/postgresql/9.6/main/postgresql.conf" \
op start timeout=60s interval=0 \
op stop timeout=60s interval=0 \
op promote timeout=15s interval=0 \
op demote timeout=120s interval=0 \
op monitor interval=30s timeout=10s role=Master \
op monitor interval=31s timeout=10s role=Slave \
op notify timeout=60 interval=0
primitive fencing-master stonith:external/ec2 \
params port=master. \
op start interval=0s timeout=60s \
op monitor interval=360s timeout=60s \
op stop interval=0s timeout=60s \
meta target-role=Started
primitive fencing-secondary stonith:external/ec2 \
params port=secondary. \
op start interval=0s timeout=60s \
op monitor interval=360s timeout=60s \
op stop interval=0s timeout=60s \
meta target-role=Started
ms PGSQL-HA PGSQL \
meta master-max=1 master-node-max=1 clone-max=2 clone-node-max=1
notify=true interleave=true
colocation IPAWSIP-WITH-MASTER inf: AWSVIP PGSQL-HA:Master
order demote-then-stop-ip Mandatory: _rsc_set_ PGSQL-HA:demote AWSVIP:stop
symmetrical=false
location loc-fence-master. fencing-master -inf: master.
location loc-fence-secondary. fencing-secondary -inf: secondary.
order promote-then-ip Mandatory: _rsc_set_ PGSQL-HA:promote AWSVIP:start
symmetrical=false
property cib-bootstrap-options: \
have-watchdog=false \
dc-version=1.1.14-70404b0 \
cluster-infrastructure=corosync \
cluster-name=psql-ha \
stonith-enabled=true \
no-quorum-policy=ignore \
maintenance-mode=false \
last-lrm-refresh=1556635192
rsc_defaults rsc-options: \
resource-stickiness=10 \
migration-threshold=2
Pacemaker is unable to start postgres master again:
crm status
Last updated: Tue Apr 30 15:25:38 2019 Last change: Tue Apr 30 15:08:43
2019 by root via cibadmin on master
Stack: corosync
Current DC: secondary (version 1.1.14-70404b0) - partition with quorum
2 nodes and 5 resources configured
Node master: UNCLEAN (*online*)
*Online*: [ secondary ]
Full list of resources:
*fencing-master* (stonith:external/ec2): *Started* secondary
*fencing-secondary* (stonith:external/ec2): *Started* master
*Master*/*Slave* Set: PGSQL-HA [PGSQL]
*PGSQL* (ocf::heartbeat:pgsqlms): FAILED master
*Slave*s: [ secondary ]
*AWSVIP* (ocf::heartbeat:awsvip): *Started* master
Failed Actions:
* PGSQL_stop_0 on master '*unknown error*' (1): call=24, status=*complete*,
exitreason='Unexpected state for instance "PGSQL" (returned 1)',
last-rc-change='Tue Apr 30 15:09:43 2019', queued=0ms, exec=100ms
On Mon, 29 Apr 2019 at 18:59, 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 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.
>
> Yes, this needs documentation indeed ...
> _______________________________________________
> 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/20190430/fdc01b57/attachment-0001.html>
-------------- next part --------------
Apr 30 15:08:33 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c89fba0 for uid=0 gid=0 pid=13764 id=9efac681-2719-46c0-93c6-bccafaca0c54
Apr 30 15:08:33 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13764-13)
Apr 30 15:08:33 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13764]
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:33 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:33 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13764-13)
Apr 30 15:08:33 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13764-13) state:2
Apr 30 15:08:33 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-response-13340-13764-13-header
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-event-13340-13764-13-header
Apr 30 15:08:33 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-request-13340-13764-13-header
Apr 30 15:08:34 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Apr 30 15:08:34 [13345] master crmd: debug: throttle_load_avg: Current load is 0.010000 (full: 0.01 0.00 0.00 1/228 13764)
Apr 30 15:08:34 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:08:42 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c89fba0 for uid=0 gid=0 pid=13774 id=866f181f-8cb5-4aac-aada-383718eaa70c
Apr 30 15:08:42 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13774-13)
Apr 30 15:08:42 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13774]
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:42 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:42 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13774-13)
Apr 30 15:08:42 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13774-13) state:2
Apr 30 15:08:42 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13774-13-header
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13774-13-header
Apr 30 15:08:42 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13774-13-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13815]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13815-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13815]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13815-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13815]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13815-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13815-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-13815-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-13815-24-header
Apr 30 15:08:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c89fba0 for uid=0 gid=0 pid=13824 id=85141aaf-4389-414f-a8e7-519fbb104813
Apr 30 15:08:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13824-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13824]
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13824-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13824-13) state:2
Apr 30 15:08:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13824-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13824-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13824-13-header
Apr 30 15:08:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c89fba0 for uid=0 gid=0 pid=13830 id=cbf603a0-538a-4416-8db4-1b2fa632d188
Apr 30 15:08:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13830-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13830]
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Forwarding cib_apply_diff operation for section 'all' to master (origin=local/cibadmin/2)
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: debug: xml_patch_version_check: Can apply patch 0.58.5 to 0.58.4
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.58.4 2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.0 c698578b38328283633792cc371fa17c
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: + /cib: @epoch=59, @num_updates=0
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/configuration/resources: <master id="PGSQL-HA"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <meta_attributes id="PGSQL-HA-meta_attributes">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="master-max" value="1" id="PGSQL-HA-meta_attributes-master-max"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="master-node-max" value="1" id="PGSQL-HA-meta_attributes-master-node-max"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="clone-max" value="2" id="PGSQL-HA-meta_attributes-clone-max"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="clone-node-max" value="1" id="PGSQL-HA-meta_attributes-clone-node-max"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="notify" value="true" id="PGSQL-HA-meta_attributes-notify"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="interleave" value="true" id="PGSQL-HA-meta_attributes-interleave"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </meta_attributes>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <primitive id="PGSQL" class="ocf" provider="heartbeat" type="pgsqlms">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <instance_attributes id="PGSQL-instance_attributes">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="pgdata" value="/var/lib/postgresql/9.6/main" id="PGSQL-instance_attributes-pgdata"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="bindir" value="/usr/lib/postgresql/9.6/bin" id="PGSQL-instance_attributes-bindir"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="pghost" value="/var/run/postgresql/" id="PGSQL-instance_attributes-pghost"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="recovery_template" value="/etc/postgresql/9.6/main/recovery.conf.pcmk" id="PGSQL-instance_attributes-recovery_template"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="start_opts" value="-c config_file=/etc/postgresql/9.6/main/postgresql.conf" id="PGSQL-instance_attributes-start_opts"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </instance_attributes>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <operations>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="start" timeout="60s" interval="0" id="PGSQL-start-0"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="stop" timeout="60s" interval="0" id="PGSQL-stop-0"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="promote" timeout="15s" interval="0" id="PGSQL-promote-0"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="demote" timeout="120s" interval="0" id="PGSQL-demote-0"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="monitor" interval="30s" timeout="10s" role="Master" id="PGSQL-monitor-30s"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="monitor" interval="31s" timeout="10s" role="Slave" id="PGSQL-monitor-31s"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <op name="notify" timeout="60" interval="0" id="PGSQL-notify-0"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </operations>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </primitive>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </master>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/configuration/resources: <primitive id="AWSVIP" class="ocf" provider="heartbeat" type="awsvip"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <instance_attributes id="AWSVIP-instance_attributes">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="secondary_private_ip" value="10.x.x.x" id="AWSVIP-instance_attributes-secondary_private_ip"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <nvpair name="api_delay" value="5" id="AWSVIP-instance_attributes-api_delay"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </instance_attributes>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </primitive>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/configuration/constraints: <rsc_colocation id="IPAWSIP-WITH-MASTER" score="INFINITY" rsc="AWSVIP" with-rsc="PGSQL-HA" with-rsc-role="Master"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/configuration/constraints: <rsc_order id="promote-then-ip" kind="Mandatory" symmetrical="false"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_set action="promote" id="promote-then-ip-0">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_ref id="PGSQL-HA"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </resource_set>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_set action="start" id="promote-then-ip-1">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_ref id="AWSVIP"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </resource_set>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </rsc_order>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/configuration/constraints: <rsc_order id="demote-then-stop-ip" kind="Mandatory" symmetrical="false"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_set action="demote" id="demote-then-stop-ip-0">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_ref id="PGSQL-HA"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </resource_set>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_set action="stop" id="demote-then-stop-ip-1">
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <resource_ref id="AWSVIP"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </resource_set>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </rsc_order>
Apr 30 15:08:43 [13340] master cib: debug: activateCibXml: Triggering CIB write for cib_apply_diff op
Apr 30 15:08:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.0 to 0.58.4
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: Stop all active resources: false
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: Default stickiness: 0
Apr 30 15:08:43 [13341] master stonith-ng: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:08:43 [13341] master stonith-ng: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:08:43 [13341] master stonith-ng: debug: cib_device_update: Device fencing-secondary is allowed on master: score=0
Apr 30 15:08:43 [13341] master stonith-ng: debug: stonith_device_register: Device 'fencing-secondary' already existed in device list (1 active devices)
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Completed cib_apply_diff operation for section 'all': OK (rc=0, origin=master/cibadmin/2, version=0.59.0)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13830-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13830-13) state:2
Apr 30 15:08:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13830-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13830-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13830-13-header
Apr 30 15:08:43 [13340] master cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-4.raw
Apr 30 15:08:43 [13340] master cib: debug: cib_file_write_with_digest: Writing CIB to disk
Apr 30 15:08:43 [13340] master cib: info: cib_file_write_with_digest: Wrote version 0.59.0 of the CIB to disk (digest: 3afe7296c419eded0296db814287873c)
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_info operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=0, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_info operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=0, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_register operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=1, notify=1, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_info operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=0, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=16, reply=1, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: log_execute: executing - rsc:PGSQL action:monitor call_id:16
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_info operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=0, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: child_waitpid: wait(13832) = 0: Success (0)
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_register operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=1, notify=1, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_info operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=0, reply=0, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=20, reply=1, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: debug: log_execute: executing - rsc:AWSVIP action:monitor call_id:20
Apr 30 15:08:43 [13340] master cib: debug: cib_file_write_with_digest: Wrote digest 3afe7296c419eded0296db814287873c to disk
Apr 30 15:08:43 [13340] master cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.cTVEP6 (digest: /var/lib/pacemaker/cib/cib.KeNmPS)
Apr 30 15:08:43 [13340] master cib: debug: cib_file_write_with_digest: Activating /var/lib/pacemaker/cib/cib.cTVEP6
Apr 30 15:08:43 [13846] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:08:43 [13846] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13846-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13846]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13846-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13846-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-13846-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-13846-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13846-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13846]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13846] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13846-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13846-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-13846-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-13846-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-13846-24-header
Apr 30 15:08:43 [13846] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:08:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c896520 for uid=0 gid=0 pid=13848 id=3788e203-94c2-42ff-9816-abd38a769361
Apr 30 15:08:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13848-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13848]
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13848] master crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: Stop all active resources: false
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: Default stickiness: 0
Apr 30 15:08:43 [13848] master crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:08:43 [13848] master crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:08:43 [13848] master crm_resource: info: determine_online_status_fencing: Node master is active
Apr 30 15:08:43 [13848] master crm_resource: info: determine_online_status: Node master is online
Apr 30 15:08:43 [13848] master crm_resource: info: determine_online_status_fencing: Node secondary is active
Apr 30 15:08:43 [13848] master crm_resource: info: determine_online_status: Node secondary is online
Apr 30 15:08:43 [13848] master crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Apr 30 15:08:43 [13848] master crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13848-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13848-13) state:2
Apr 30 15:08:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13848-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13848-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13848-13-header
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13848-13-header
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13848-13-header
Apr 30 15:08:43 [13848] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13848-13-header
Apr 30 15:08:43 [13848] master crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _get_controldata: found: {
'state' => 'shut down',
'wal_level' => 'replica',
'redo' => '0/7000290',
'tl' => '1'
}
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: pgsql_monitor: monitor is a probe
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _get_action_timeout: known timeout: 10
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_isready -h /var/run/postgresql/ -p 5432 -d postgres -t 70"
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: pgsql_monitor: instance "PGSQL" is not listening
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_ctl --pgdata /var/lib/postgresql/9.6/main status"
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _confirm_stopped: no postmaster process found for instance "PGSQL"
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _get_controldata: found: {
'tl' => '1',
'redo' => '0/7000290',
'wal_level' => 'replica',
'state' => 'shut down'
}
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _controldata: instance "PGSQL" state is "shut down"
pgsqlms(PGSQL)[13832]: 2019/04/30_15:08:43 DEBUG: _confirm_stopped: instance "PGSQL" controldata indicates that the instance was propertly shut down
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: PGSQL_monitor_0:13832 - exited with rc=7
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: PGSQL_monitor_0:13832:stderr [ -- empty -- ]
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: PGSQL_monitor_0:13832:stdout [ /var/run/postgresql/:5432 - no response ]
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: PGSQL_monitor_0:13832:stdout [ pg_ctl: no server running ]
Apr 30 15:08:43 [13342] master lrmd: debug: log_finished: finished - rsc:PGSQL action:monitor call_id:16 pid:13832 exit-code:7 exec-time:160ms queue-time:1ms
Apr 30 15:08:43 [13342] master lrmd: debug: child_waitpid: wait(13833) = 0: Resource temporarily unavailable (11)
Apr 30 15:08:43 [13345] master crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after monitor op complete (interval=0)
Apr 30 15:08:43 [13863] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:08:43 [13863] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13863-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13863]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-13863-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13863-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13863-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-13863-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-13863-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13863-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13863]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13863] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-13863-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13863-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13863-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-13863-24-header
Apr 30 15:08:43 [13863] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-13863-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-13863-24-header
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13345] master crmd: info: action_synced_wait: Managed pgsqlms_meta-data_0 process 13855 exited with rc=0
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.0 2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.1 (null)
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=1
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources: <lrm_resource id="PGSQL" type="pgsqlms" class="ocf" provider="heartbeat"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <lrm_rsc_op id="PGSQL_last_0" operation_key="PGSQL_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="6:3:7:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="0:7;6:3:7:513b50a2-5d7d-4393-b85b-005332286dad" on_node="secondary" call-id="16" rc-code="7" op-status="0" interv
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </lrm_resource>
Apr 30 15:08:43 [13345] master crmd: notice: process_lrm_event: Operation PGSQL_monitor_0: not running (node=master, call=16, rc=7, cib-update=15, confirmed=true)
Apr 30 15:08:43 [13345] master crmd: notice: process_lrm_event: master-PGSQL_monitor_0:16 [ /var/run/postgresql/:5432 - no response\npg_ctl: no server running\n ]
Apr 30 15:08:43 [13345] master crmd: debug: update_history_cache: Updating history for 'PGSQL' with monitor op
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=secondary/crmd/63, version=0.59.1)
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/15)
Apr 30 15:08:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.1 to 0.59.0
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.1 2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.2 (null)
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources: <lrm_resource id="PGSQL" type="pgsqlms" class="ocf" provider="heartbeat"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <lrm_rsc_op id="PGSQL_last_0" operation_key="PGSQL_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="4:3:7:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="0:7;4:3:7:513b50a2-5d7d-4393-b85b-005332286dad" on_node="master" call-id="16" rc-code="7" op-status="0" inter
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </lrm_resource>
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=master/crmd/15, version=0.59.2)
Apr 30 15:08:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.2 to 0.59.1
Apr 30 15:08:43 [13345] master crmd: debug: do_lrm_rsc_op: Stopped 0 recurring operations in preparation for PGSQL_start_0
Apr 30 15:08:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=21, reply=1, notify=0, exit=1226186800
Apr 30 15:08:43 [13342] master lrmd: info: log_execute: executing - rsc:PGSQL action:start call_id:21
Apr 30 15:08:43 [13871] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:08:43 [13871] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13871-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13871]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-13871-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13871-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13871-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-13871-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-13871-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-13871-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] connecting to client [13871]
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:08:43 [13871] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-13871-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] HUP conn (6852-13871-24)
Apr 30 15:08:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-13871-24) state:2
Apr 30 15:08:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-13871-24-header
Apr 30 15:08:43 [13871] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-13871-24-header
Apr 30 15:08:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-13871-24-header
Apr 30 15:08:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c8a8390 for uid=0 gid=0 pid=13873 id=29c31d4b-4374-491b-9915-554849c8b7d5
Apr 30 15:08:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13873-13)
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13873]
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:43 [13873] master crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: Stop all active resources: false
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: Default stickiness: 0
Apr 30 15:08:43 [13873] master crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:08:43 [13873] master crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:08:43 [13873] master crm_resource: info: determine_online_status_fencing: Node master is active
Apr 30 15:08:43 [13873] master crm_resource: info: determine_online_status: Node master is online
Apr 30 15:08:43 [13873] master crm_resource: info: determine_online_status_fencing: Node secondary is active
Apr 30 15:08:43 [13873] master crm_resource: info: determine_online_status: Node secondary is online
Apr 30 15:08:43 [13873] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on master to PGSQL:0
Apr 30 15:08:43 [13873] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on secondary to PGSQL:0
Apr 30 15:08:43 [13873] master crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Apr 30 15:08:43 [13873] master crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13873-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13873-13)
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13873-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13873-13) state:2
Apr 30 15:08:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:43 [13873] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13873-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-13873-13-header
Apr 30 15:08:43 [13873] master crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-13873-13-header
Apr 30 15:08:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-13873-13-header
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _get_controldata: found: {
'redo' => '0/7000290',
'tl' => '1',
'state' => 'shut down',
'wal_level' => 'replica'
}
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _get_action_timeout: known timeout: 60
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_isready -h /var/run/postgresql/ -p 5432 -d postgres -t 120"
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: pgsql_monitor: instance "PGSQL" is not listening
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_ctl --pgdata /var/lib/postgresql/9.6/main status"
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _confirm_stopped: no postmaster process found for instance "PGSQL"
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _get_controldata: found: {
'state' => 'shut down',
'tl' => '1',
'redo' => '0/7000290',
'wal_level' => 'replica'
}
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _controldata: instance "PGSQL" state is "shut down"
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _confirm_stopped: instance "PGSQL" controldata indicates that the instance was propertly shut down
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _get_controldata: found: {
'redo' => '0/7000290',
'tl' => '1',
'state' => 'shut down',
'wal_level' => 'replica'
}
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: pgsql_start: instance "PGSQL" is not running, starting it as a secondary
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _create_recovery_conf: get replication configuration from the template file "/etc/postgresql/9.6/main/recovery.conf.pcmk"
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _create_recovery_conf: write the replication configuration to "/var/lib/postgresql/9.6/main/recovery.conf" file
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _get_action_timeout: known timeout: 60
pgsqlms(PGSQL)[13864]: 2019/04/30_15:08:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_ctl --pgdata /var/lib/postgresql/9.6/main -w --timeout 120 start -o -c config_file=/etc/postgresql/9.6/main/postgresql.conf"
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.2 2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.3 (null)
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=3
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources: <lrm_resource id="AWSVIP" type="awsvip" class="ocf" provider="heartbeat"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <lrm_rsc_op id="AWSVIP_last_0" operation_key="AWSVIP_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="7:3:7:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="0:7;7:3:7:513b50a2-5d7d-4393-b85b-005332286dad" on_node="secondary" call-id="20" rc-code="7" op-status="0" inte
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </lrm_resource>
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=secondary/crmd/64, version=0.59.3)
Apr 30 15:08:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.3 to 0.59.2
awsvip(AWSVIP)[13833]: 2019/04/30_15:08:43 DEBUG: AWSVIP monitor : 0
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: AWSVIP_monitor_0:13833 - exited with rc=0
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: AWSVIP_monitor_0:13833:stderr [ -- empty -- ]
Apr 30 15:08:43 [13342] master lrmd: debug: operation_finished: AWSVIP_monitor_0:13833:stdout [ -- empty -- ]
Apr 30 15:08:43 [13342] master lrmd: debug: log_finished: finished - rsc:AWSVIP action:monitor call_id:20 pid:13833 exit-code:0 exec-time:788ms queue-time:0ms
Apr 30 15:08:43 [13342] master lrmd: debug: child_waitpid: wait(13864) = 0: Resource temporarily unavailable (11)
Apr 30 15:08:43 [13345] master crmd: debug: create_operation_update: do_update_resource: Updating resource AWSVIP after monitor op complete (interval=0)
Apr 30 15:08:43 [13345] master crmd: info: action_synced_wait: Managed awsvip_meta-data_0 process 13904 exited with rc=0
Apr 30 15:08:43 [13345] master crmd: notice: process_lrm_event: Operation AWSVIP_monitor_0: ok (node=master, call=20, rc=0, cib-update=16, confirmed=true)
Apr 30 15:08:43 [13345] master crmd: debug: update_history_cache: Updating history for 'AWSVIP' with monitor op
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/16)
Apr 30 15:08:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.3 2
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.4 (null)
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=4
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/lrm[@id='1']/lrm_resources: <lrm_resource id="AWSVIP" type="awsvip" class="ocf" provider="heartbeat"/>
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <lrm_rsc_op id="AWSVIP_last_failure_0" operation_key="AWSVIP_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="5:3:7:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="0:0;5:3:7:513b50a2-5d7d-4393-b85b-005332286dad" on_node="master" call-id="20" rc-code="0" op-status
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ <lrm_rsc_op id="AWSVIP_last_0" operation_key="AWSVIP_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="5:3:7:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="0:0;5:3:7:513b50a2-5d7d-4393-b85b-005332286dad" on_node="master" call-id="20" rc-code="0" op-status="0" int
Apr 30 15:08:43 [13340] master cib: info: cib_perform_op: ++ </lrm_resource>
Apr 30 15:08:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=master/crmd/16, version=0.59.4)
Apr 30 15:08:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.4 to 0.59.3
Apr 30 15:08:44 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:44 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.4 2
Apr 30 15:08:44 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.5 (null)
Apr 30 15:08:44 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=5
Apr 30 15:08:44 [13340] master 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_start_0, @operation=start, @transition-key=14:3:0:513b50a2-5d7d-4393-b85b-005332286dad, @transition-magic=0:0;14:3:0:513b50a2-5d7d-4393-b85b-005332286dad, @call-id=21, @rc-code=0, @exec-time=1211
Apr 30 15:08:44 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=secondary/crmd/65, version=0.59.5)
Apr 30 15:08:44 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.5 to 0.59.4
Apr 30 15:08:46 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c898300 for uid=0 gid=0 pid=13915 id=2ee1f7c2-86ba-47d8-acb5-85cd01168c86
Apr 30 15:08:46 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13915-13)
Apr 30 15:08:46 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13915]
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:46 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:46 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13915-13)
Apr 30 15:08:46 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13915-13) state:2
Apr 30 15:08:46 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-response-13340-13915-13-header
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-event-13340-13915-13-header
Apr 30 15:08:46 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-request-13340-13915-13-header
Apr 30 15:08:49 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:54 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c898300 for uid=0 gid=0 pid=13940 id=3cada005-000e-4cfe-bf7b-89b3bcfa086d
Apr 30 15:08:54 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-13940-13)
Apr 30 15:08:54 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [13940]
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:08:54 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:08:54 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-13940-13)
Apr 30 15:08:54 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-13940-13) state:2
Apr 30 15:08:54 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-response-13340-13940-13-header
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-event-13340-13940-13-header
Apr 30 15:08:54 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_ro-request-13340-13940-13-header
Apr 30 15:09:04 [13345] master crmd: debug: throttle_cib_load: cib load: 0.001000 (3 ticks in 30s)
Apr 30 15:09:04 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 1/235 13971)
Apr 30 15:09:04 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:09:34 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Apr 30 15:09:34 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 1/235 14031)
Apr 30 15:09:34 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:09:43 [13342] master lrmd: debug: child_kill_helper: Kill pid 13864's group
Apr 30 15:09:43 [13342] master lrmd: warning: child_timeout_callback: PGSQL_start_0 process (PID 13864) timed out
Apr 30 15:09:43 [13342] master lrmd: warning: operation_finished: PGSQL_start_0:13864 - timed out after 60000ms
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stderr [ -- empty -- ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ /var/run/postgresql/:5432 - no response ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ pg_ctl: no server running ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ waiting for server to start....2019-04-30 15:08:43.644 UTC [13888] LOG: database system was shut down at 2019-04-30 15:06:23 UTC ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.644 UTC [13888] LOG: entering standby mode ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.649 UTC [13888] LOG: consistent recovery state reached at 0/7000300 ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.649 UTC [13888] LOG: invalid record length at 0/7000300: wanted 24, got 0 ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.674 UTC [13892] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.676 UTC [13894] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.676 UTC [13891] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.702 UTC [13896] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.704 UTC [13897] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.704 UTC [13895] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.713 UTC [13893] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.714 UTC [13898] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.741 UTC [13899] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:43.743 UTC [13900] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:44.591 UTC [13907] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:45.593 UTC [13908] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:46.594 UTC [13916] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:47.596 UTC [13917] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:48.598 UTC [13918] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:48.696 UTC [13920] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:48.696 UTC [13921] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:48.696 UTC [13919] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:48.735 UTC [13922] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:48.737 UTC [13923] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:49.600 UTC [13924] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:50.602 UTC [13925] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:51.604 UTC [13926] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:52.606 UTC [13927] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:53.608 UTC [13928] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:53.701 UTC [13930] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:53.702 UTC [13931] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:53.702 UTC [13929] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:53.739 UTC [13932] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:53.740 UTC [13933] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:54.610 UTC [13941] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:55.612 UTC [13942] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:56.614 UTC [13943] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:57.616 UTC [13944] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:58.618 UTC [13945] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:08:58.707 UTC [13947] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:58.707 UTC [13948] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:58.708 UTC [13946] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:58.744 UTC [13949] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:58.745 UTC [13950] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:08:59.620 UTC [13953] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:00.621 UTC [13962] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:01.623 UTC [13963] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:02.625 UTC [13964] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:03.627 UTC [13965] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:03.713 UTC [13967] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:03.714 UTC [13968] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:03.714 UTC [13966] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:03.748 UTC [13969] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:03.749 UTC [13970] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:04.629 UTC [13971] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:05.631 UTC [13972] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:06.633 UTC [13973] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:07.635 UTC [13974] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:08.637 UTC [13975] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:08.718 UTC [13977] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:08.719 UTC [13978] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:08.719 UTC [13976] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:08.754 UTC [13979] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:08.755 UTC [13980] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:09.639 UTC [13981] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:10.641 UTC [13982] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:11.643 UTC [13983] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:12.645 UTC [13984] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:13.647 UTC [13985] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:13.724 UTC [13987] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:13.725 UTC [13988] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:13.725 UTC [13986] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:13.759 UTC [13989] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:13.761 UTC [13990] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:14.649 UTC [13991] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:15.651 UTC [13992] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:16.653 UTC [13993] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:17.655 UTC [13994] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:18.657 UTC [13995] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:18.726 UTC [13997] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:18.727 UTC [13998] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:18.727 UTC [13996] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:18.765 UTC [13999] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:18.766 UTC [14000] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:19.659 UTC [14001] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:20.661 UTC [14002] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:21.663 UTC [14003] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:22.665 UTC [14004] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:23.667 UTC [14005] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:23.733 UTC [14007] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:23.734 UTC [14008] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:23.734 UTC [14006] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:23.769 UTC [14009] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:23.770 UTC [14010] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:24.669 UTC [14011] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:25.671 UTC [14012] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:26.673 UTC [14013] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:27.675 UTC [14014] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:28.677 UTC [14015] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:28.734 UTC [14017] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:28.735 UTC [14018] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:28.735 UTC [14016] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:28.775 UTC [14019] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:28.776 UTC [14020] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:29.679 UTC [14021] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:30.680 UTC [14022] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:31.682 UTC [14023] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:32.684 UTC [14024] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:33.686 UTC [14025] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:33.740 UTC [14027] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:33.741 UTC [14028] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:33.741 UTC [14026] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:33.780 UTC [14029] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:33.782 UTC [14030] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:34.688 UTC [14031] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:35.690 UTC [14032] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:36.693 UTC [14033] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:37.694 UTC [14034] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:38.696 UTC [14035] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:38.746 UTC [14037] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:38.747 UTC [14038] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:38.747 UTC [14036] FATAL: could not connect to the primary server: FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:38.787 UTC [14039] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:38.788 UTC [14040] replication@[unknown] FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ 2019-04-30 15:09:39.699 UTC [14041] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:40.701 UTC [14042] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:41.702 UTC [14043] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ .2019-04-30 15:09:42.704 UTC [14044] postgres at postgres FATAL: the database system is starting up ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_start_0:13864:stdout [ . ]
Apr 30 15:09:43 [13342] master lrmd: info: log_finished: finished - rsc:PGSQL action:start call_id:21 pid:13864 exit-code:1 exec-time:60003ms queue-time:0ms
Apr 30 15:09:43 [13345] master crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after start op Timed Out (interval=0)
Apr 30 15:09:43 [14052] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:09:43 [14052] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14052-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14052]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-14052-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14052-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14052-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-14052-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-14052-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14052-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14052]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14052] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-14052-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14052-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14052-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-14052-24-header
Apr 30 15:09:43 [14052] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-14052-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-14052-24-header
Apr 30 15:09:43 [13345] master crmd: info: action_synced_wait: Managed pgsqlms_meta-data_0 process 14045 exited with rc=0
Apr 30 15:09:43 [13345] master crmd: notice: process_lrm_event: master-PGSQL_start_0:21 [ /var/run/postgresql/:5432 - no response\npg_ctl: no server running\nwaiting for server to start....2019-04-30 15:08:43.644 UTC [13888] LOG: database system was shut down at 2019-04-30 15:06:23 UTC\n2019-04-30 15:08:43.644 UTC [13888] LOG: entering standby mode\n2019-04-30 15:08:43.649 UTC [13888] LOG: consistent recovery state reached at 0/7000300\n2019-04-30 15:0
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/17)
Apr 30 15:09:43 [13345] master crmd: debug: update_history_cache: Updating history for 'PGSQL' with start op
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.5 2
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.6 (null)
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=6
Apr 30 15:09:43 [13340] master 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_start_0, @operation=start, @transition-key=12:3:0:513b50a2-5d7d-4393-b85b-005332286dad, @transition-magic=2:1;12:3:0:513b50a2-5d7d-4393-b85b-005332286dad, @call-id=21, @rc-code=1, @op-status=2, @exec-time=60003, @queue-time=0
Apr 30 15:09:43 [13340] master 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_failure_0" operation_key="PGSQL_start_0" operation="start" crm-debug-origin="do_update_resource" crm_feature_set="3.0.10" transition-key="12:3:0:513b50a2-5d7d-4393-b85b-005332286dad" transition-magic="2:1;12:3:0:513b50a2-5d7d-4393-b85b-005332286dad" on_node="master" call-id="21" r
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=master/crmd/17, version=0.59.6)
Apr 30 15:09:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.6 to 0.59.5
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.6 2
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.7 (null)
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=7
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']: <transient_attributes id="1"/>
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ <instance_attributes id="status-1">
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ <nvpair id="status-1-fail-count-PGSQL" name="fail-count-PGSQL" value="INFINITY"/>
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ </instance_attributes>
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ </transient_attributes>
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=secondary/attrd/12, version=0.59.7)
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=22, reply=1, notify=0, exit=1226186800
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.7 2
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.8 (null)
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=8
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: ++ /cib/status/node_state[@id='1']/transient_attributes[@id='1']/instance_attributes[@id='status-1']: <nvpair id="status-1-last-failure-PGSQL" name="last-failure-PGSQL" value="1556636983"/>
Apr 30 15:09:43 [13342] master lrmd: info: log_execute: executing - rsc:PGSQL action:notify call_id:22
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=secondary/attrd/13, version=0.59.8)
Apr 30 15:09:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.7 to 0.59.6
Apr 30 15:09:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.8 to 0.59.7
Apr 30 15:09:43 [14060] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:09:43 [14060] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14060-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14060]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14060-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14060-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-14060-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-14060-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14060-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14060]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14060] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14060-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14060-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-14060-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-14060-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-14060-24-header
Apr 30 15:09:43 [14060] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c898300 for uid=0 gid=0 pid=14062 id=86ef8e27-d5b3-4c64-a8f5-e371c34d6091
Apr 30 15:09:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-14062-13)
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [14062]
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14062] master crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: Stop all active resources: false
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: Default stickiness: 0
Apr 30 15:09:43 [14062] master crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:09:43 [14062] master crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:09:43 [14062] master crm_resource: info: determine_online_status_fencing: Node master is active
Apr 30 15:09:43 [14062] master crm_resource: info: determine_online_status: Node master is online
Apr 30 15:09:43 [14062] master crm_resource: info: determine_online_status_fencing: Node secondary is active
Apr 30 15:09:43 [14062] master crm_resource: info: determine_online_status: Node secondary is online
Apr 30 15:09:43 [14062] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on master to PGSQL:0
Apr 30 15:09:43 [14062] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14062] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14062] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14062] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14062] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14062] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14062] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on secondary to PGSQL:1
Apr 30 15:09:43 [14062] master crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Apr 30 15:09:43 [14062] master crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14062-13-header
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14062-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-14062-13)
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-14062-13) state:2
Apr 30 15:09:43 [14062] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14062-13-header
Apr 30 15:09:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14062-13-header
Apr 30 15:09:43 [14062] master crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14062-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14062-13-header
pgsqlms(PGSQL)[14053]: 2019/04/30_15:09:43 DEBUG: _get_controldata: found: {
'wal_level' => 'replica',
'redo' => '0/7000290',
'state' => 'in archive recovery',
'tl' => '1'
}
pgsqlms(PGSQL)[14053]: 2019/04/30_15:09:43 DEBUG: pgsql_notify: environment variables: {
'active' => [],
'demote' => [],
'inactive' => [
{
'rsc' => 'PGSQL:0'
},
{
'rsc' => 'PGSQL:1'
}
],
'master' => [],
'operation' => 'start',
'promote' => [],
'slave' => [],
'start' => [
{
'rsc' => 'PGSQL:0',
'uname' => 'master'
},
{
'rsc' => 'PGSQL:1',
'uname' => 'secondary'
}
],
'stop' => [],
'type' => 'post'
}
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14053 - exited with rc=0
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14053:stderr [ -- empty -- ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14053:stdout [ -- empty -- ]
Apr 30 15:09:43 [13342] master lrmd: info: log_finished: finished - rsc:PGSQL action:notify call_id:22 pid:14053 exit-code:0 exec-time:87ms queue-time:0ms
Apr 30 15:09:43 [13345] master crmd: debug: create_operation_update: send_direct_ack: Updating resource PGSQL after notify op complete (interval=0)
Apr 30 15:09:43 [13345] master crmd: debug: send_direct_ack: ACK'ing resource op PGSQL_notify_0 from 45:3:0:513b50a2-5d7d-4393-b85b-005332286dad: lrm_invoke-lrmd-1556636983-5
Apr 30 15:09:43 [13345] master crmd: notice: process_lrm_event: Operation PGSQL_notify_0: ok (node=master, call=22, rc=0, cib-update=0, confirmed=true)
Apr 30 15:09:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=23, reply=1, notify=0, exit=1226186800
Apr 30 15:09:43 [13342] master lrmd: info: log_execute: executing - rsc:PGSQL action:notify call_id:23
Apr 30 15:09:43 [14072] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:09:43 [14072] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14072-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14072]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14072-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14072-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-14072-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-14072-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14072-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14072]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14072] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14072-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14072-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-14072-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-14072-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-14072-24-header
Apr 30 15:09:43 [14072] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c898300 for uid=0 gid=0 pid=14074 id=72f3a812-48b1-47a9-80d2-3c62cf5b66c8
Apr 30 15:09:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-14074-13)
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [14074]
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14074] master crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: Stop all active resources: false
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: Default stickiness: 0
Apr 30 15:09:43 [14074] master crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:09:43 [14074] master crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:09:43 [14074] master crm_resource: info: determine_online_status_fencing: Node master is active
Apr 30 15:09:43 [14074] master crm_resource: info: determine_online_status: Node master is online
Apr 30 15:09:43 [14074] master crm_resource: info: determine_online_status_fencing: Node secondary is active
Apr 30 15:09:43 [14074] master crm_resource: info: determine_online_status: Node secondary is online
Apr 30 15:09:43 [14074] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on master to PGSQL:0
Apr 30 15:09:43 [14074] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14074] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14074] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14074] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14074] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14074] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14074] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on secondary to PGSQL:1
Apr 30 15:09:43 [14074] master crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Apr 30 15:09:43 [14074] master crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14074-13-header
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14074-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-14074-13)
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-14074-13) state:2
Apr 30 15:09:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:09:43 [14074] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14074-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14074-13-header
Apr 30 15:09:43 [14074] master crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14074-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14074-13-header
pgsqlms(PGSQL)[14065]: 2019/04/30_15:09:43 DEBUG: _get_controldata: found: {
'wal_level' => 'replica',
'redo' => '0/7000290',
'tl' => '1',
'state' => 'in archive recovery'
}
pgsqlms(PGSQL)[14065]: 2019/04/30_15:09:43 DEBUG: pgsql_notify: environment variables: {
'active' => [
{
'rsc' => 'PGSQL:0',
'uname' => 'master'
},
{
'rsc' => 'PGSQL:1',
'uname' => 'secondary'
}
],
'demote' => [],
'inactive' => [],
'master' => [],
'operation' => 'stop',
'promote' => [],
'slave' => [
$VAR1->{'active'}[0],
$VAR1->{'active'}[1]
],
'start' => [],
'stop' => [
{
'rsc' => 'PGSQL:0',
'uname' => 'master'
}
],
'type' => 'pre'
}
pgsqlms(PGSQL)[14065]: 2019/04/30_15:09:43 DEBUG: _get_controldata: found: {
'tl' => '1',
'state' => 'in archive recovery',
'redo' => '0/7000290',
'wal_level' => 'replica'
}
pgsqlms(PGSQL)[14065]: 2019/04/30_15:09:43 DEBUG: _controldata: instance "PGSQL" state is "in archive recovery"
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14065 - exited with rc=0
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14065:stderr [ -- empty -- ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_notify_0:14065:stdout [ -- empty -- ]
Apr 30 15:09:43 [13342] master lrmd: info: log_finished: finished - rsc:PGSQL action:notify call_id:23 pid:14065 exit-code:0 exec-time:88ms queue-time:0ms
Apr 30 15:09:43 [13345] master crmd: debug: create_operation_update: send_direct_ack: Updating resource PGSQL after notify op complete (interval=0)
Apr 30 15:09:43 [13345] master crmd: debug: send_direct_ack: ACK'ing resource op PGSQL_notify_0 from 43:4:0:513b50a2-5d7d-4393-b85b-005332286dad: lrm_invoke-lrmd-1556636983-6
Apr 30 15:09:43 [13345] master crmd: notice: process_lrm_event: Operation PGSQL_notify_0: ok (node=master, call=23, rc=0, cib-update=0, confirmed=true)
Apr 30 15:09:43 [13345] master crmd: debug: do_lrm_rsc_op: Stopped 0 recurring operations in preparation for PGSQL_stop_0
Apr 30 15:09:43 [13342] master lrmd: debug: process_lrmd_message: Processed lrmd_rsc_exec operation from 5bb1bdeb-f0d1-4c94-855f-e41e9238520f: rc=24, reply=1, notify=0, exit=1226186800
Apr 30 15:09:43 [13342] master lrmd: info: log_execute: executing - rsc:PGSQL action:stop call_id:24
Apr 30 15:09:43 [14086] master crm_node: info: get_cluster_type: Verifying cluster type: 'corosync'
Apr 30 15:09:43 [14086] master crm_node: info: get_cluster_type: Assuming an active 'corosync' cluster
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14086-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14086]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14086-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14086-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-response-6852-14086-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-event-6852-14086-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cpg-request-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-request-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-response-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cpg-event-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: get_local_nodeid: Local nodeid is 1
Apr 30 15:09:43 [6852] master corosync debug [QB ] IPC credentials authenticated (6852-14086-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] connecting to client [14086]
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [6852] master corosync debug [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_open_2: shm size:1048589; real_size:1052672; rb->word_size:263168
Apr 30 15:09:43 [14086] master crm_node: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [6852] master corosync debug [QB ] HUP conn (6852-14086-24)
Apr 30 15:09:43 [6852] master corosync debug [QB ] qb_ipcs_disconnect(6852-14086-24) state:2
Apr 30 15:09:43 [6852] master corosync debug [QB ] epoll_ctl(del): Bad file descriptor (9)
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-response-6852-14086-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-event-6852-14086-24-header
Apr 30 15:09:43 [6852] master corosync debug [QB ] Free'ing ringbuffer: /dev/shm/qb-cmap-request-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-request-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-response-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cmap-event-6852-14086-24-header
Apr 30 15:09:43 [14086] master crm_node: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: crm_client_new: Connecting 0x559d0c898300 for uid=0 gid=0 pid=14088 id=a42c52a0-37e7-4014-b736-654308c54e6a
Apr 30 15:09:43 [13340] master cib: debug: handle_new_connection: IPC credentials authenticated (13340-14088-13)
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_shm_connect: connecting to client [14088]
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_open_2: shm size:524301; real_size:528384; rb->word_size:132096
Apr 30 15:09:43 [14088] master crm_resource: debug: cib_native_signon_raw: Connection to CIB successful
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: STONITH timeout: 60000
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: STONITH of failed nodes is enabled
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: Stop all active resources: false
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: Default stickiness: 0
Apr 30 15:09:43 [14088] master crm_resource: notice: unpack_config: On loss of CCM Quorum: Ignore
Apr 30 15:09:43 [14088] master crm_resource: debug: unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0
Apr 30 15:09:43 [14088] master crm_resource: info: determine_online_status_fencing: Node master is active
Apr 30 15:09:43 [14088] master crm_resource: info: determine_online_status: Node master is online
Apr 30 15:09:43 [14088] master crm_resource: info: determine_online_status_fencing: Node secondary is active
Apr 30 15:09:43 [14088] master crm_resource: info: determine_online_status: Node secondary is online
Apr 30 15:09:43 [14088] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on master to PGSQL:0
Apr 30 15:09:43 [14088] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14088] master crm_resource: warning: unpack_rsc_op_failure: Processing failed op start for PGSQL:0 on master: unknown error (1)
Apr 30 15:09:43 [14088] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14088] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14088] master crm_resource: debug: determine_op_status: AWSVIP_monitor_0 on master returned 'ok' (0) instead of the expected value: 'not running' (7)
Apr 30 15:09:43 [14088] master crm_resource: info: determine_op_status: Operation monitor found resource AWSVIP active on master
Apr 30 15:09:43 [14088] master crm_resource: debug: find_anonymous_clone: Internally renamed PGSQL on secondary to PGSQL:1
Apr 30 15:09:43 [14088] master crm_resource: debug: cli_resource_print_attribute: Looking up notify in PGSQL:0
Apr 30 15:09:43 [14088] master crm_resource: debug: cib_native_signoff: Signing out of the CIB Service
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_ipcc_disconnect: qb_ipcc_disconnect()
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14088-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_dispatch_connection_request: HUP conn (13340-14088-13)
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14088-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_ipcs_disconnect: qb_ipcs_disconnect(13340-14088-13) state:2
Apr 30 15:09:43 [13340] master cib: debug: crm_client_destroy: Destroying 0 events
Apr 30 15:09:43 [14088] master crm_resource: debug: qb_rb_close: Closing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14088-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-response-13340-14088-13-header
Apr 30 15:09:43 [14088] master crm_resource: info: crm_xml_cleanup: Cleaning up memory from libxml2
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-event-13340-14088-13-header
Apr 30 15:09:43 [13340] master cib: debug: qb_rb_close: Free'ing ringbuffer: /dev/shm/qb-cib_rw-request-13340-14088-13-header
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _get_controldata: found: {
'state' => 'in archive recovery',
'wal_level' => 'replica',
'redo' => '0/7000290',
'tl' => '1'
}
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _get_action_timeout: known timeout: 60
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _get_action_timeout: known timeout: 60
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_isready -h /var/run/postgresql/ -p 5432 -d postgres -t 120"
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: pgsql_monitor: instance "PGSQL" is not listening
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _runas: launching as "postgres" command "/usr/lib/postgresql/9.6/bin/pg_ctl --pgdata /var/lib/postgresql/9.6/main status"
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _confirm_stopped: no postmaster process found for instance "PGSQL"
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _get_controldata: found: {
'redo' => '0/7000290',
'wal_level' => 'replica',
'tl' => '1',
'state' => 'in archive recovery'
}
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 DEBUG: _controldata: instance "PGSQL" state is "in archive recovery"
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 ERROR: Instance "PGSQL" controldata indicates a running secondary instance, the instance has probably crashed
pgsqlms(PGSQL)[14079]: 2019/04/30_15:09:43 ERROR: Unexpected state for instance "PGSQL" (returned 1)
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_stop_0:14079 - exited with rc=1
Apr 30 15:09:43 [13342] master lrmd: notice: operation_finished: PGSQL_stop_0:14079:stderr [ ocf-exit-reason:Instance "PGSQL" controldata indicates a running secondary instance, the instance has probably crashed ]
Apr 30 15:09:43 [13342] master lrmd: notice: operation_finished: PGSQL_stop_0:14079:stderr [ ocf-exit-reason:Unexpected state for instance "PGSQL" (returned 1) ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_stop_0:14079:stdout [ /var/run/postgresql/:5432 - no response ]
Apr 30 15:09:43 [13342] master lrmd: debug: operation_finished: PGSQL_stop_0:14079:stdout [ pg_ctl: no server running ]
Apr 30 15:09:43 [13342] master lrmd: info: log_finished: finished - rsc:PGSQL action:stop call_id:24 pid:14079 exit-code:1 exec-time:100ms queue-time:0ms
Apr 30 15:09:43 [13345] master crmd: debug: create_operation_update: do_update_resource: Updating resource PGSQL after stop op complete (interval=0)
Apr 30 15:09:43 [13345] master crmd: notice: process_lrm_event: Operation PGSQL_stop_0: unknown error (node=master, call=24, rc=1, cib-update=18, confirmed=true)
Apr 30 15:09:43 [13345] master crmd: notice: process_lrm_event: master-PGSQL_stop_0:24 [ ocf-exit-reason:Instance "PGSQL" controldata indicates a running secondary instance, the instance has probably crashed\nocf-exit-reason:Unexpected state for instance "PGSQL" (returned 1)\n ]
Apr 30 15:09:43 [13345] master crmd: debug: update_history_cache: Updating history for 'PGSQL' with stop op
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/18)
Apr 30 15:09:43 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: --- 0.59.8 2
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: Diff: +++ 0.59.9 (null)
Apr 30 15:09:43 [13340] master cib: info: cib_perform_op: + /cib: @num_updates=9
Apr 30 15:09:43 [13340] master 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_stop_0, @operation=stop, @transition-key=2:4:0:513b50a2-5d7d-4393-b85b-005332286dad, @transition-magic=0:1;2:4:0:513b50a2-5d7d-4393-b85b-005332286dad, @call-id=24, @op-status=0, @last-run=1556636983, @last-rc-change=1556636983, @exec-time=100, @exit-reason=Unexpected state for
Apr 30 15:09:43 [13340] master 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_failure_0']: @operation_key=PGSQL_stop_0, @operation=stop, @transition-key=2:4:0:513b50a2-5d7d-4393-b85b-005332286dad, @transition-magic=0:1;2:4:0:513b50a2-5d7d-4393-b85b-005332286dad, @call-id=24, @op-status=0, @last-run=1556636983, @last-rc-change=1556636983, @exec-time=100, @exit-reason=Unexpected st
Apr 30 15:09:43 [13340] master cib: info: cib_process_request: Completed cib_modify operation for section status: OK (rc=0, origin=master/crmd/18, version=0.59.9)
Apr 30 15:09:43 [13341] master stonith-ng: debug: xml_patch_version_check: Can apply patch 0.59.9 to 0.59.8
Apr 30 15:09:43 [13341] master stonith-ng: debug: stonith_command: Processing st_query 0 from secondary ( 0)
Apr 30 15:09:43 [13341] master stonith-ng: debug: stonith_query: Query <stonith_command __name__="stonith_command" t="stonith-ng" st_async_id="31bed3f2-765b-4864-86c0-09e655d38dba" st_op="st_query" st_callid="2" st_callopt="0" st_remote_op="31bed3f2-765b-4864-86c0-09e655d38dba" st_target="master" st_device_action="reboot" st_origin="secondary" st_clientid="f723eba0-c4ee-4205-8f36-e1dfc9b66021" st_clientname="crmd.32647" st_timeout="60" src=
Apr 30 15:09:43 [13341] master stonith-ng: debug: get_capable_devices: Searching through 1 devices to see what is capable of action (reboot) for target master
Apr 30 15:09:43 [13341] master stonith-ng: debug: search_devices_record_result: Finished Search. 0 devices can perform action (reboot) on node master
Apr 30 15:09:43 [13341] master stonith-ng: debug: stonith_query_capable_device_cb: Found 0 matching devices for 'master'
Apr 30 15:09:43 [13341] master stonith-ng: debug: stonith_command: Processed st_query from secondary: OK (0)
Apr 30 15:09:48 [13340] master cib: debug: cib_acl_enabled: CIB ACL is disabled
Apr 30 15:10:04 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Apr 30 15:10:04 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 1/229 14108)
Apr 30 15:10:04 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:10:34 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Apr 30 15:10:34 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 1/229 14108)
Apr 30 15:10:34 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_command: Processing st_notify reply 0 from secondary ( 0)
Apr 30 15:10:51 [13341] master stonith-ng: debug: process_remote_stonith_exec: Marking call to reboot for master on behalf of crmd.32647 at 31bed3f2-765b-4864-86c0-09e655d38dba.test-rsy: Timer expired (-62)
Apr 30 15:10:51 [13341] master stonith-ng: notice: remote_op_done: Operation reboot of master by secondary for crmd.32647 at secondary.31bed3f2: Timer expired
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_command: Processed st_notify reply from secondary: OK (0)
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_command: Processing st_query 0 from secondary ( 0)
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_query: Query <stonith_command __name__="stonith_command" t="stonith-ng" st_async_id="387e80e5-0e82-4150-8956-c6a385df31d1" st_op="st_query" st_callid="3" st_callopt="0" st_remote_op="387e80e5-0e82-4150-8956-c6a385df31d1" st_target="master" st_device_action="reboot" st_origin="secondary" st_clientid="f723eba0-c4ee-4205-8f36-e1dfc9b66021" st_clientname="crmd.32647" st_timeout="60" src=
Apr 30 15:10:51 [13341] master stonith-ng: debug: get_capable_devices: Searching through 1 devices to see what is capable of action (reboot) for target master
Apr 30 15:10:51 [13341] master stonith-ng: debug: search_devices_record_result: Finished Search. 0 devices can perform action (reboot) on node master
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_query_capable_device_cb: Found 0 matching devices for 'master'
Apr 30 15:10:51 [13341] master stonith-ng: debug: stonith_command: Processed st_query from secondary: OK (0)
Apr 30 15:11:04 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000000 (0 ticks in 30s)
Apr 30 15:11:04 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 2/229 14108)
Apr 30 15:11:04 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:11:34 [13345] master crmd: debug: throttle_cib_load: cib load: 0.000333 (1 ticks in 30s)
Apr 30 15:11:34 [13345] master crmd: debug: throttle_load_avg: Current load is 0.000000 (full: 0.00 0.00 0.00 2/229 14113)
Apr 30 15:11:34 [13345] master crmd: debug: throttle_io_load: Current IO load is 0.000000
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_command: Processing st_notify reply 0 from secondary ( 0)
Apr 30 15:11:58 [13341] master stonith-ng: debug: process_remote_stonith_exec: Marking call to reboot for master on behalf of crmd.32647 at 387e80e5-0e82-4150-8956-c6a385df31d1.test-rsy: Timer expired (-62)
Apr 30 15:11:58 [13341] master stonith-ng: notice: remote_op_done: Operation reboot of master by secondary for crmd.32647 at secondary.387e80e5: Timer expired
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_command: Processed st_notify reply from secondary: OK (0)
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_command: Processing st_query 0 from secondary ( 0)
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_query: Query <stonith_command __name__="stonith_command" t="stonith-ng" st_async_id="38333c24-0ae3-4a1e-82ab-4281391223fd" st_op="st_query" st_callid="4" st_callopt="0" st_remote_op="38333c24-0ae3-4a1e-82ab-4281391223fd" st_target="master" st_device_action="reboot" st_origin="secondary" st_clientid="f723eba0-c4ee-4205-8f36-e1dfc9b66021" st_clientname="crmd.32647" st_timeout="60" src=
Apr 30 15:11:58 [13341] master stonith-ng: debug: get_capable_devices: Searching through 1 devices to see what is capable of action (reboot) for target master
Apr 30 15:11:58 [13341] master stonith-ng: debug: search_devices_record_result: Finished Search. 0 devices can perform action (reboot) on node master
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_query_capable_device_cb: Found 0 matching devices for 'master'
Apr 30 15:11:58 [13341] master stonith-ng: debug: stonith_command: Processed st_query from secondary: OK (0)
More information about the Users
mailing list