[Pacemaker] Resources are not started

[Matti Linnanvuori]

Andreas Kurz:
> full logs around this restart would be interesting ... you tested all 
> your own OCF scripts with ocf-tester and they are sane?

Yes, I tested all of our own OCF scripts and they seem to work most of the time.

The following is the tail of file /var/log/corosync.log after crm resource restart DB-daemon:

Nov 08 16:40:26 iac-pgis cib: [2095]: info: write_cib_contents: Wrote version 0.127.0 of the CIB to disk (digest: 695ae492c8ab41162865fad817e1a748)
Nov 08 16:40:26 iac-pgis cib: [2095]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.5GMRoq (digest: /var/lib/heartbeat/crm/cib.xGG5ep)
Nov 08 16:41:03 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[26] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:41:03 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:41:04 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1424] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:41:04 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:41:09 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[26] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:41:09 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:41:10 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1424] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:41:10 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: - <cib admin_epoch="0" epoch="127" num_updates="1" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -   <configuration >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -     <resources >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -       <primitive id="DB-daemon" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -         <meta_attributes id="DB-daemon-meta_attributes" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -           <nvpair value="Started" id="DB-daemon-meta_attributes-target-role" />
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -         </meta_attributes>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -       </primitive>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -     </resources>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -   </configuration>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: - </cib>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: + <cib admin_epoch="0" epoch="128" num_updates="1" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +   <configuration >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +     <resources >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +       <primitive id="DB-daemon" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +         <meta_attributes id="DB-daemon-meta_attributes" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +           <nvpair value="Stopped" id="DB-daemon-meta_attributes-target-role" />
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +         </meta_attributes>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +       </primitive>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +     </resources>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +   </configuration>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: + </cib>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: cib_process_request: Operation complete: op cib_replace for section resources (origin=local/cibadmin/2, version=0.128.1): ok (rc=0)
Nov 08 16:41:30 iac-pgis cib: [4026]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-26.raw
Nov 08 16:41:30 iac-pgis cib: [4026]: info: write_cib_contents: Wrote version 0.128.0 of the CIB to disk (digest: 50a169997d0d9f6f7de07e3e38eec71f)
Nov 08 16:41:30 iac-pgis cib: [4026]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.BBnEZ8 (digest: /var/lib/heartbeat/crm/cib.txMEqQ)
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: - <cib admin_epoch="0" epoch="128" num_updates="1" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -   <configuration >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -     <resources >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -       <primitive id="DB-daemon" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -         <meta_attributes id="DB-daemon-meta_attributes" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -           <nvpair value="Stopped" id="DB-daemon-meta_attributes-target-role" />
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -         </meta_attributes>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -       </primitive>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -     </resources>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: -   </configuration>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: - </cib>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: + <cib admin_epoch="0" epoch="129" num_updates="1" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +   <configuration >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +     <resources >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +       <primitive id="DB-daemon" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +         <meta_attributes id="DB-daemon-meta_attributes" >
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +           <nvpair value="Started" id="DB-daemon-meta_attributes-target-role" />
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +         </meta_attributes>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +       </primitive>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +     </resources>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: +   </configuration>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: log_data_element: cib:diff: + </cib>
Nov 08 16:41:30 iac-pgis cib: [2560]: info: cib_process_request: Operation complete: op cib_replace for section resources (origin=local/cibadmin/2, version=0.129.1): ok (rc=0)
Nov 08 16:41:30 iac-pgis cib: [4057]: info: write_cib_contents: Archived previous version as /var/lib/heartbeat/crm/cib-27.raw
Nov 08 16:41:30 iac-pgis cib: [4057]: info: write_cib_contents: Wrote version 0.129.0 of the CIB to disk (digest: 7853e43088a01f3af1d92260934bef45)
Nov 08 16:41:30 iac-pgis cib: [4057]: info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.M8mMG9 (digest: /var/lib/heartbeat/crm/cib.JkJUOR)
Nov 08 16:42:52 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:42:52 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:42:57 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:42:57 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:43:02 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:43:02 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:43:07 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:43:07 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:43:12 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:43:12 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms
Nov 08 16:43:38 iac-pgis lrmd: [2561]: info: perform_op:2884: operation monitor[1372] on ocf::statusmgr::statusmgr-daemon for client 2564, its parameters: CRM_meta_name=[monitor] crm_feature_set=[3.0.2] CRM_meta_timeout=[20000] CRM_meta_interval=[5000] statusmgr_binary=[/etc/init.d/iac-statusmgr]  for rsc is already running.
Nov 08 16:43:38 iac-pgis lrmd: [2561]: info: perform_op:2894: postponing all ops on resource statusmgr-daemon by 1000 ms

Matti Linnanvuori