[Pacemaker] Resources are not started

[Dejan Muhamedagic]

Hi,

On Tue, Nov 08, 2011 at 04:46:53PM +0200, Matti Linnanvuori wrote:
> 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

How long does the monitor take? I didn't see your configuration,
but if it takes longer than the interval you set for monitor,
this looks like exactly that case.

Thanks,

Dejan

> Matti Linnanvuori
> 
> 
> _______________________________________________
> Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
> 
> Project Home: http://www.clusterlabs.org
> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
> Bugs: http://developerbugs.linux-foundation.org/enter_bug.cgi?product=Pacemaker