logd[17885]: 2007/10/23_19:44:48 info: logd started with /etc/logd.cf.
logd[17886]: 2007/10/23_19:44:48 info: G_main_add_SignalHandler: Added signal handler for signal 15
logd[17885]: 2007/10/23_19:44:48 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[17906]: 2007/10/23_19:44:48 info: Enabling logging daemon 
heartbeat[17906]: 2007/10/23_19:44:48 info: logfile and debug file are those specified in logd config file (default /etc/logd.cf)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(keepalive,2)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(deadtime,30)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(initdead,30)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(warntime,20)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(udpport,694)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(bcast,eth2)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(node,prec370d)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(node,prec370e)
heartbeat[17906]: 2007/10/23_19:44:48 debug: uid=hacluster, gid=<null>
heartbeat[17906]: 2007/10/23_19:44:48 debug: uid=hacluster, gid=<null>
heartbeat[17906]: 2007/10/23_19:44:48 debug: uid=<null>, gid=haclient
heartbeat[17906]: 2007/10/23_19:44:48 debug: uid=root, gid=<null>
heartbeat[17906]: 2007/10/23_19:44:48 debug: uid=<null>, gid=haclient
heartbeat[17906]: 2007/10/23_19:44:48 debug: Beginning authentication parsing
heartbeat[17906]: 2007/10/23_19:44:48 debug: 16 max authentication methods
heartbeat[17906]: 2007/10/23_19:44:48 debug: Keyfile opened
heartbeat[17906]: 2007/10/23_19:44:48 debug: Keyfile perms OK
heartbeat[17906]: 2007/10/23_19:44:48 debug: 16 max authentication methods
heartbeat[17906]: 2007/10/23_19:44:48 debug: Found authentication method [sha1]
heartbeat[17906]: 2007/10/23_19:44:48 info: AUTH: i=1: key = 0x5d92f8, auth=0x2a96103900, authname=sha1
heartbeat[17906]: 2007/10/23_19:44:48 debug: Outbound signing method is 1
heartbeat[17906]: 2007/10/23_19:44:48 debug: Authentication parsing complete [1]
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(cluster,linux-ha)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(hopfudge,1)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(baud,19200)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(auto_failback,legacy)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(hbgenmethod,file)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(realtime,true)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(msgfmt,classic)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(conn_logd_time,60)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(log_badpack,true)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(syslogmsgfmt,false)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(coredumps,true)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(autojoin,none)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(uuidfrom,file)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(compression,zlib)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(compression_threshold,2)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(traditional_compression,no)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(max_rexmit_delay,250)
heartbeat[17906]: 2007/10/23_19:44:48 debug: Setting max_rexmit_delay to 250 ms
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(record_config_changes,on)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(record_pengine_inputs,on)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(enable_config_writes,on)
heartbeat[17906]: 2007/10/23_19:44:48 debug: add_option(memreserve,6500)
heartbeat[17906]: 2007/10/23_19:44:48 info: **************************
heartbeat[17906]: 2007/10/23_19:44:48 info: Configuration validated. Starting heartbeat 2.1.3
heartbeat[17906]: 2007/10/23_19:44:48 debug: HA configuration OK.  Heartbeat starting.
heartbeat[17907]: 2007/10/23_19:44:48 info: heartbeat: version 2.1.3
heartbeat[17907]: 2007/10/23_19:44:48 info: Heartbeat generation: 921
heartbeat[17907]: 2007/10/23_19:44:48 debug: uuid is:9d9ca527-cea9-470c-9e03-e49fe5630bba
heartbeat[17907]: 2007/10/23_19:44:48 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[17907]: 2007/10/23_19:44:48 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[17907]: 2007/10/23_19:44:48 info: Removing /var/run/heartbeat/rsctmp failed, recreating.
heartbeat[17907]: 2007/10/23_19:44:48 debug: opening bcast eth2 (UDP/IP broadcast)
heartbeat[17907]: 2007/10/23_19:44:48 debug: FIFO process pid: 17910
heartbeat[17907]: 2007/10/23_19:44:48 debug: glib: SO_BINDTODEVICE(r) set for device eth2
heartbeat[17907]: 2007/10/23_19:44:48 info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth2
heartbeat[17907]: 2007/10/23_19:44:48 debug: write process pid: 17911
heartbeat[17907]: 2007/10/23_19:44:48 debug: read child process pid: 17912
heartbeat[17907]: 2007/10/23_19:44:48 info: glib: UDP Broadcast heartbeat closed on port 694 interface eth2 - Status: 1
heartbeat[17907]: 2007/10/23_19:44:48 info: G_main_add_SignalHandler: Added signal handler for signal 17
heartbeat[17907]: 2007/10/23_19:44:48 debug: Limiting CPU: 42 CPU seconds every 60000 milliseconds
heartbeat[17907]: 2007/10/23_19:44:48 debug: pid 17907 locked in memory.
heartbeat[17907]: 2007/10/23_19:44:48 debug: Waiting for child processes to start
heartbeat[17907]: 2007/10/23_19:44:48 info: Local status now set to: 'up'
heartbeat[17907]: 2007/10/23_19:44:48 debug: All your child process are belong to us
heartbeat[17907]: 2007/10/23_19:44:48 debug: Starting local status message @ 2000 ms intervals
heartbeat[17910]: 2007/10/23_19:44:49 debug: pid 17910 locked in memory.
heartbeat[17910]: 2007/10/23_19:44:49 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[17912]: 2007/10/23_19:44:49 debug: pid 17912 locked in memory.
heartbeat[17912]: 2007/10/23_19:44:49 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[17911]: 2007/10/23_19:44:49 debug: pid 17911 locked in memory.
heartbeat[17911]: 2007/10/23_19:44:49 debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
heartbeat[17907]: 2007/10/23_19:44:49 info: Link prec370d:eth2 up.
heartbeat[17907]: 2007/10/23_19:44:49 debug: sending reqnodes msg to node prec370d
heartbeat[17907]: 2007/10/23_19:44:49 info: Status update for node prec370d: status up
heartbeat[17907]: 2007/10/23_19:44:49 debug: Status seqno: 2 msgtime: 1193136288
heartbeat[17907]: 2007/10/23_19:44:49 info: Link prec370e:eth2 up.
heartbeat[17907]: 2007/10/23_19:44:50 debug: Get a reqnodes message from prec370d
heartbeat[17907]: 2007/10/23_19:44:50 debug: get_delnodelist: delnodelist= 
heartbeat[17907]: 2007/10/23_19:44:50 debug: Get a repnodes msg from prec370d
heartbeat[17907]: 2007/10/23_19:44:50 debug: nodelist received:prec370d prec370e 
heartbeat[17907]: 2007/10/23_19:44:50 info: Comm_now_up(): updating status to active
heartbeat[17907]: 2007/10/23_19:44:50 info: Local status now set to: 'active'
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/ccm" (90,90)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/cib" (90,90)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/lrmd -r" (0,0)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/stonithd" (0,0)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/attrd" (90,90)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/crmd" (90,90)
heartbeat[17907]: 2007/10/23_19:44:50 info: Starting child client "/usr/lib64/heartbeat/mgmtd -v" (0,0)
heartbeat[17916]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/ccm" as uid 90  gid 90 (pid 17916)
heartbeat[17917]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/cib" as uid 90  gid 90 (pid 17917)
heartbeat[17918]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/lrmd -r" as uid 0  gid 0 (pid 17918)
heartbeat[17919]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/stonithd" as uid 0  gid 0 (pid 17919)
heartbeat[17920]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/attrd" as uid 90  gid 90 (pid 17920)
heartbeat[17921]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/crmd" as uid 90  gid 90 (pid 17921)
heartbeat[17922]: 2007/10/23_19:44:50 info: Starting "/usr/lib64/heartbeat/mgmtd -v" as uid 0  gid 0 (pid 17922)
ccm[17916]: 2007/10/23_19:44:50 debug: Signing in with Heartbeat
heartbeat[17907]: 2007/10/23_19:44:50 debug: APIregistration_dispatch() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: process_registerevent() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: client->gsource = 0x5eaa08
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*process_registerevent*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*APIregistration_dispatch*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: Checking client authorization for client ccm (90:90)
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[17907]: 2007/10/23_19:44:50 debug: Signing on API client 17916 (ccm)
cib[17917]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 15
cib[17917]: 2007/10/23_19:44:50 info: G_main_add_TriggerHandler: Added signal manual handler
cib[17917]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 17
cib[17917]: 2007/10/23_19:44:50 info: main: Retrieval of a per-action CIB: disabled
cib[17917]: 2007/10/23_19:44:50 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17917]: 2007/10/23_19:44:50 WARN: validate_cib_digest: No on-disk digest present
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk] <cib admin_epoch="0" epoch="1" num_updates="1" have_quorum="false" cib_feature_revision="1.3" generated="false">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]   <configuration>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     <crm_config>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       <cluster_property_set id="idCluseterPropertySet">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <attributes>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="symmetric-cluster" name="symmetric-cluster" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="no-quorum-policy" name="no-quorum-policy" value="ignore"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stonith-enabled" name="stonith-enabled" value="false"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="short-resource-names" name="short_resource_names" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="is-managed-default" name="is-managed-default" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-resource-stickiness" name="default-resource-stickiness" value="INFINITY"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stop-orphan-resources" name="stop-orphan-resources" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stop-orphan-actions" name="stop-orphan-actions" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="remove-after-stop" name="remove-after-stop" value="false"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-resource-failure-stickiness" name="default-resource-failure-stickiness" value="-INFINITY"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stonith-action" name="stonith-action" value="reboot"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-action-timeout" name="default-action-timeout" value="120s"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="dc_deadtime" name="dc_deadtime" value="10s"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="cluster_recheck_interval" name="cluster_recheck_interval" value="0"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="election_timeout" name="election_timeout" value="2min"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="shutdown_escalation" name="shutdown_escalation" value="20min"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="crmd-integration-timeout" name="crmd-integration-timeout" value="3min"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="crmd-finalization-timeout" name="crmd-finalization-timeout" value="10min"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="cluster-delay" name="cluster-delay" value="120s"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-error-series-max" name="pe-error-series-max" value="-1"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-warn-series-max" name="pe-warn-series-max" value="-1"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-input-series-max" name="pe-input-series-max" value="-1"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="startup-fencing" name="startup-fencing" value="true"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </attributes>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       </cluster_property_set>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     </crm_config>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     <nodes/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     <resources>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       <group id="grpDummy">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <primitive id="prmDummyA" class="ocf" type="Dummy" provider="heartbeat">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <operations>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAStart" name="start" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAMonitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAStop" name="stop" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           </operations>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </primitive>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <primitive id="prmDummyB" class="ocf" type="Dummy" provider="heartbeat">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <operations>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBStart" name="start" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBMonitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBStop" name="stop" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           </operations>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </primitive>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       </group>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     </resources>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     <constraints>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       <rsc_location id="rlcDummy" rsc="grpDummy">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <rule score="200" id="rulNode1">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <expression value="prec370d" attribute="#uname" operation="eq" id="expNode1"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <rule score="300" id="rulNode2">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <expression value="prec370e" attribute="#uname" operation="eq" id="expNode2"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       </rsc_location>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       <rsc_location id="ping:disconn" rsc="grpDummy">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         <rule id="ping1:disconn:rule" score="-INFINITY" boolean_op="and">
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <expression id="ping1:disconn:expr:defined" attribute="default_ping_set" operation="defined"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]           <expression id="ping1:disconn:expr:positive" attribute="default_ping_set" operation="lt" value="100"/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]       </rsc_location>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]     </constraints>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]   </configuration>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk]   <status/>
cib[17917]: 2007/10/23_19:44:50 info: log_data_element: readCibXmlFile: [on-disk] </cib>
mgmtd[17922]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 15
mgmtd[17922]: 2007/10/23_19:44:50 debug: Enabling coredumps
mgmtd[17922]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 10
mgmtd[17922]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 12
heartbeat[17907]: 2007/10/23_19:44:50 debug: APIregistration_dispatch() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: process_registerevent() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: client->gsource = 0x5f0bb8
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*process_registerevent*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*APIregistration_dispatch*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: Checking client authorization for client mgmtd (0:0)
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370d
mgmtd[17922]: 2007/10/23_19:44:50 WARN: lrm_signon: can not initiate connection
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370e
mgmtd[17922]: 2007/10/23_19:44:50 info: login to lrm: 0, ret:0
heartbeat[17907]: 2007/10/23_19:44:50 debug: Signing on API client 17922 (mgmtd)
ccm[17916]: 2007/10/23_19:44:50 info: Hostname: prec370e
lrmd[17918]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 15
lrmd[17918]: 2007/10/23_19:44:50 debug: LRM debug level set to 1
lrmd[17918]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 17
lrmd[17918]: 2007/10/23_19:44:50 debug: Enabling coredumps
lrmd[17918]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 10
lrmd[17918]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 12
lrmd[17918]: 2007/10/23_19:44:50 debug: main: run the loop...
cib[17917]: 2007/10/23_19:44:50 notice: readCibXmlFile: Enabling DTD validation on the existing (sane) configuration
lrmd[17918]: 2007/10/23_19:44:50 info: Started.
cib[17917]: 2007/10/23_19:44:50 info: startCib: CIB Initialization completed successfully
cib[17917]: 2007/10/23_19:44:50 info: cib_register_ha: Signing in with Heartbeat
heartbeat[17907]: 2007/10/23_19:44:50 debug: APIregistration_dispatch() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: process_registerevent() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: client->gsource = 0x5f0f48
cib[17917]: 2007/10/23_19:44:50 info: cib_register_ha: FSA Hostname: prec370e
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*process_registerevent*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*APIregistration_dispatch*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: Checking client authorization for client cib (90:90)
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370d
cib[17917]: 2007/10/23_19:44:50 info: ccm_connect: Registering with CCM...
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370e
cib[17917]: 2007/10/23_19:44:50 WARN: ccm_connect: CCM Activation failed
heartbeat[17907]: 2007/10/23_19:44:50 debug: Signing on API client 17917 (cib)
cib[17917]: 2007/10/23_19:44:50 WARN: ccm_connect: CCM Connection failed 1 times (30 max)
stonithd[17919]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 10
stonithd[17919]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 12
stonithd[17919]: 2007/10/23_19:44:50 debug: pid 17919 locked in memory.
heartbeat[17907]: 2007/10/23_19:44:50 debug: APIregistration_dispatch() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: process_registerevent() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: client->gsource = 0x5f2058
stonithd[17919]: 2007/10/23_19:44:50 info: Signing in with heartbeat.
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*process_registerevent*/;
stonithd[17919]: 2007/10/23_19:44:50 debug: Setting message filter mode
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*APIregistration_dispatch*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: Checking client authorization for client stonithd (0:0)
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[17907]: 2007/10/23_19:44:50 debug: Signing on API client 17919 (stonithd)
crmd[17921]: 2007/10/23_19:44:50 info: main: CRM Hg Version: eff0a9cb1d45+ tip

attrd[17920]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 15
attrd[17920]: 2007/10/23_19:44:50 debug: register_with_ha: Signing in with Heartbeat
heartbeat[17907]: 2007/10/23_19:44:50 debug: APIregistration_dispatch() {
heartbeat[17907]: 2007/10/23_19:44:50 debug: process_registerevent() {
attrd[17920]: 2007/10/23_19:44:50 info: register_with_ha: Hostname: prec370e
heartbeat[17907]: 2007/10/23_19:44:50 debug: client->gsource = 0x5f5548
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*process_registerevent*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: }/*APIregistration_dispatch*/;
heartbeat[17907]: 2007/10/23_19:44:50 debug: Checking client authorization for client attrd (90:90)
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[17907]: 2007/10/23_19:44:50 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[17907]: 2007/10/23_19:44:50 debug: Signing on API client 17920 (attrd)
stonithd[17919]: 2007/10/23_19:44:50 debug: apichan=0x519238
crmd[17921]: 2007/10/23_19:44:50 info: crmd_init: Starting crmd
crmd[17921]: 2007/10/23_19:44:50 debug: register_fsa_input_adv: crmd_init appended FSA input 1 (I_STARTUP) (cause=C_STARTUP) without data
crmd[17921]: 2007/10/23_19:44:50 debug: s_crmd_fsa: Processing I_STARTUP: [ state=S_STARTING cause=C_STARTUP origin=crmd_init ]
crmd[17921]: 2007/10/23_19:44:50 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[17921]: 2007/10/23_19:44:50 debug: do_fsa_action: actions:trace: 	// A_STARTUP
stonithd[17919]: 2007/10/23_19:44:50 debug: callback_chan=0x5197d8
crmd[17921]: 2007/10/23_19:44:50 debug: do_startup: Registering Signal Handlers
stonithd[17919]: 2007/10/23_19:44:50 notice: /usr/lib64/heartbeat/stonithd start up successfully.
crmd[17921]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 15
stonithd[17919]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 17
crmd[17921]: 2007/10/23_19:44:50 info: G_main_add_TriggerHandler: Added signal manual handler
crmd[17921]: 2007/10/23_19:44:50 debug: do_startup: Creating CIB and LRM objects
crmd[17921]: 2007/10/23_19:44:50 debug: do_startup: Init server comms
crmd[17921]: 2007/10/23_19:44:50 info: G_main_add_SignalHandler: Added signal handler for signal 17
crmd[17921]: 2007/10/23_19:44:50 debug: do_fsa_action: actions:trace: 	// A_CIB_START
heartbeat[17907]: 2007/10/23_19:44:50 info: Status update for node prec370d: status active
heartbeat[17907]: 2007/10/23_19:44:50 debug: Status seqno: 7 msgtime: 1193136290
attrd[17920]: 2007/10/23_19:44:50 info: register_with_ha: UUID: 9d9ca527-cea9-470c-9e03-e49fe5630bba
attrd[17920]: 2007/10/23_19:44:50 debug: main: CIB signon attempt 0
lrmd[17918]: 2007/10/23_19:44:51 debug: on_msg_register:client mgmtd [17922] registered
mgmtd[17922]: 2007/10/23_19:44:51 info: init_crm
cib[17917]: 2007/10/23_19:44:51 info: ccm_connect: Registering with CCM...
cib[17917]: 2007/10/23_19:44:51 WARN: ccm_connect: CCM Activation failed
cib[17917]: 2007/10/23_19:44:51 WARN: ccm_connect: CCM Connection failed 2 times (30 max)
cib[17917]: 2007/10/23_19:44:52 info: ccm_connect: Registering with CCM...
cib[17917]: 2007/10/23_19:44:52 WARN: ccm_connect: CCM Activation failed
cib[17917]: 2007/10/23_19:44:52 WARN: ccm_connect: CCM Connection failed 3 times (30 max)
ccm[17916]: 2007/10/23_19:44:53 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[17916]: 2007/10/23_19:44:53 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[17916]: 2007/10/23_19:44:53 info: G_main_add_SignalHandler: Added signal handler for signal 15
cib[17917]: 2007/10/23_19:44:53 info: ccm_connect: Registering with CCM...
cib[17917]: 2007/10/23_19:44:53 debug: ccm_connect: CCM Activation passed... all set to go!
cib[17917]: 2007/10/23_19:44:53 debug: Delaying cstatus request for 50 ms
cib[17917]: 2007/10/23_19:44:53 info: cib_init: Starting cib mainloop
cib[17923]: 2007/10/23_19:44:53 debug: write_cib_contents: Archiving current version
cib[17923]: 2007/10/23_19:44:53 WARN: validate_cib_digest: No on-disk digest present
cib[17923]: 2007/10/23_19:44:53 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17923]: 2007/10/23_19:44:53 WARN: validate_cib_digest: No on-disk digest present
cib[17923]: 2007/10/23_19:44:53 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[17923]: 2007/10/23_19:44:53 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17923]: 2007/10/23_19:44:53 WARN: validate_cib_digest: No on-disk digest present
cib[17923]: 2007/10/23_19:44:53 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[17923]: 2007/10/23_19:44:53 WARN: validate_cib_digest: No on-disk digest present
cib[17923]: 2007/10/23_19:44:53 debug: write_cib_contents: Verified CIB archive
heartbeat[17907]: 2007/10/23_19:44:53 debug: APIregistration_dispatch() {
cib[17917]: 2007/10/23_19:44:53 info: cib_client_status_callback: Status update: Client prec370e/cib now has status [join]
crmd[17921]: 2007/10/23_19:44:53 debug: cib_native_signon: Connection to CIB successful
heartbeat[17907]: 2007/10/23_19:44:53 debug: process_registerevent() {
cib[17917]: 2007/10/23_19:44:53 debug: set_connected_peers: We now have 1 active peers
crmd[17921]: 2007/10/23_19:44:53 info: do_cib_control: CIB connection established
attrd[17920]: 2007/10/23_19:44:53 debug: cib_native_signon: Connection to CIB successful
heartbeat[17907]: 2007/10/23_19:44:53 debug: client->gsource = 0x604098
cib[17917]: 2007/10/23_19:44:53 info: cib_null_callback: Setting cib_refresh_notify callbacks for crmd: on
crmd[17921]: 2007/10/23_19:44:53 debug: do_fsa_action: actions:trace: 	// A_HA_CONNECT
heartbeat[17907]: 2007/10/23_19:44:53 debug: }/*process_registerevent*/;
crmd[17921]: 2007/10/23_19:44:53 debug: register_with_ha: Signing in with Heartbeat
heartbeat[17907]: 2007/10/23_19:44:53 debug: }/*APIregistration_dispatch*/;
crmd[17921]: 2007/10/23_19:44:53 info: register_with_ha: Hostname: prec370e
heartbeat[17907]: 2007/10/23_19:44:53 debug: Checking client authorization for client crmd (90:90)
heartbeat[17907]: 2007/10/23_19:44:53 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[17907]: 2007/10/23_19:44:53 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[17907]: 2007/10/23_19:44:53 debug: Signing on API client 17921 (crmd)
cib[17917]: 2007/10/23_19:44:53 info: cib_client_status_callback: Status update: Client prec370d/cib now has status [join]
cib[17917]: 2007/10/23_19:44:53 debug: set_connected_peers: We now have 2 active peers
cib[17917]: 2007/10/23_19:44:53 info: cib_client_status_callback: Status update: Client prec370e/cib now has status [online]
cib[17917]: 2007/10/23_19:44:53 info: cib_null_callback: Setting cib_diff_notify callbacks for mgmtd: on
cib[17923]: 2007/10/23_19:44:53 debug: write_cib_contents: Wrote CIB to disk
cib[17923]: 2007/10/23_19:44:53 info: write_cib_contents: Wrote version 0.1.1 of the CIB to disk (digest: d7bee52adf07eb41d5c0a4af8dcfc4e1)
cib[17923]: 2007/10/23_19:44:53 debug: write_cib_contents: Wrote digest to disk
cib[17923]: 2007/10/23_19:44:53 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17923]: 2007/10/23_19:44:53 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[17923]: 2007/10/23_19:44:53 WARN: validate_cib_digest: No on-disk digest present
cib[17923]: 2007/10/23_19:44:53 debug: write_cib_contents: Wrote and verified CIB
cib[17917]: 2007/10/23_19:44:54 info: cib_client_status_callback: Status update: Client prec370d/cib now has status [online]
crmd[17921]: 2007/10/23_19:44:54 info: register_with_ha: UUID: 9d9ca527-cea9-470c-9e03-e49fe5630bba
ccm[17916]: 2007/10/23_19:44:54 debug: recv msg hbapi-clstat from prec370e, status:join
crmd[17921]: 2007/10/23_19:44:54 debug: Delaying cstatus request for 23 ms
crmd[17921]: 2007/10/23_19:44:54 info: populate_cib_nodes: Requesting the list of configured nodes
ccm[17916]: 2007/10/23_19:44:55 debug: recv msg status from prec370d, status:active
ccm[17916]: 2007/10/23_19:44:55 debug: status of node prec370d: active -> active
heartbeat[17907]: 2007/10/23_19:44:55 WARN: 1 lost packet(s) for [prec370d] [17:19]
heartbeat[17907]: 2007/10/23_19:44:55 info: No pkts missing from prec370d!
crmd[17921]: 2007/10/23_19:44:55 notice: populate_cib_nodes: Node: prec370e (uuid: 9d9ca527-cea9-470c-9e03-e49fe5630bba)
mgmtd[17922]: 2007/10/23_19:44:55 debug: main: run the loop...
mgmtd[17922]: 2007/10/23_19:44:55 info: Started.
ccm[17916]: 2007/10/23_19:44:56 debug: recv msg hbapi-clstat from prec370d, status:join
crmd[17921]: 2007/10/23_19:44:56 notice: populate_cib_nodes: Node: prec370d (uuid: 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6)
crmd[17921]: 2007/10/23_19:44:56 info: do_ha_control: Connected to Heartbeat
crmd[17921]: 2007/10/23_19:44:56 debug: do_fsa_action: actions:trace: 	// A_READCONFIG
crmd[17921]: 2007/10/23_19:44:56 debug: do_fsa_action: actions:trace: 	// A_LRM_CONNECT
crmd[17921]: 2007/10/23_19:44:56 debug: do_lrm_control: Connecting to the LRM
lrmd[17918]: 2007/10/23_19:44:56 debug: on_msg_register:client crmd [17921] registered
ccm[17916]: 2007/10/23_19:44:56 debug: recv msg CCM_TYPE_PROTOVERSION from prec370d, status:[null ptr]
crmd[17921]: 2007/10/23_19:44:56 debug: do_lrm_control: LRM connection established
ccm[17916]: 2007/10/23_19:44:56 debug: send msg CCM_TYPE_PROTOVERSION to cluster, status:[null]
crmd[17921]: 2007/10/23_19:44:56 debug: do_fsa_action: actions:trace: 	// A_CCM_CONNECT
ccm[17916]: 2007/10/23_19:44:56 debug: node state CCM_STATE_NONE -> CCM_STATE_VERSION_REQUEST
crmd[17921]: 2007/10/23_19:44:56 info: do_ccm_control: CCM connection established... waiting for first callback
crmd[17921]: 2007/10/23_19:44:56 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[17921]: 2007/10/23_19:44:56 info: do_started: Delaying start, CCM (0000000000100000) not connected
crmd[17921]: 2007/10/23_19:44:56 debug: register_fsa_input_adv: do_started prepended FSA input 2 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
crmd[17921]: 2007/10/23_19:44:56 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
crmd[17921]: 2007/10/23_19:44:56 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
crmd[17921]: 2007/10/23_19:44:56 debug: fsa_dump_inputs: Added input: 0000000000000100 (R_CIB_CONNECTED)
crmd[17921]: 2007/10/23_19:44:56 debug: fsa_dump_inputs: Added input: 0000000000000800 (R_LRM_CONNECTED)
crmd[17921]: 2007/10/23_19:44:56 info: crmd_init: Starting crmd's mainloop
crmd[17921]: 2007/10/23_19:44:56 notice: crmd_client_status_callback: Status update: Client prec370e/crmd now has status [online]
mgmtd[17922]: 2007/10/23_19:44:56 debug: update cib finished
cib[17924]: 2007/10/23_19:44:56 debug: write_cib_contents: Archiving current version
cib[17924]: 2007/10/23_19:44:56 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17924]: 2007/10/23_19:44:56 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[17924]: 2007/10/23_19:44:56 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
cib[17924]: 2007/10/23_19:44:56 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17924]: 2007/10/23_19:44:56 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[17924]: 2007/10/23_19:44:56 debug: write_cib_contents: Verified CIB archive
cib[17924]: 2007/10/23_19:44:56 debug: write_cib_contents: Wrote CIB to disk
cib[17924]: 2007/10/23_19:44:56 info: write_cib_contents: Wrote version 0.1.1 of the CIB to disk (digest: d83c35612485f15f3af47845d04b001a)
cib[17924]: 2007/10/23_19:44:56 debug: write_cib_contents: Wrote digest to disk
cib[17924]: 2007/10/23_19:44:56 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17924]: 2007/10/23_19:44:56 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[17924]: 2007/10/23_19:44:56 debug: write_cib_contents: Wrote and verified CIB
ccm[17916]: 2007/10/23_19:44:56 debug: recv msg CCM_TYPE_PROTOVERSION from prec370e, status:[null ptr]
ccm[17916]: 2007/10/23_19:44:56 debug: No quorum selected,using default quorum plugin(majority:twonodes)
ccm[17916]: 2007/10/23_19:44:56 debug: quorum plugin: majority
ccm[17916]: 2007/10/23_19:44:56 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
ccm[17916]: 2007/10/23_19:44:56 debug: total_node_count=2, total_quorum_votes=200
ccm[17916]: 2007/10/23_19:44:56 debug: quorum plugin: twonodes
ccm[17916]: 2007/10/23_19:44:56 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
crmd[17921]: 2007/10/23_19:44:56 notice: crmd_client_status_callback: Status update: Client prec370e/crmd now has status [online]
ccm[17916]: 2007/10/23_19:44:56 debug: total_node_count=2, total_quorum_votes=200
ccm[17916]: 2007/10/23_19:44:56 info: Break tie for 2 nodes cluster
ccm[17916]: 2007/10/23_19:44:56 debug: node state CCM_STATE_VERSION_REQUEST -> CCM_STATE_JOINED
ccm[17916]: 2007/10/23_19:44:56 debug: dump current membership 0x2a959cf028
ccm[17916]: 2007/10/23_19:44:56 debug: 	leader=prec370e
ccm[17916]: 2007/10/23_19:44:56 debug: 	transition=1
ccm[17916]: 2007/10/23_19:44:56 debug: 	status=CCM_STATE_JOINED
ccm[17916]: 2007/10/23_19:44:56 debug: 	has_quorum=1
cib[17917]: 2007/10/23_19:44:56 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[17916]: 2007/10/23_19:44:56 debug: 	nodename=prec370e bornon=1
cib[17917]: 2007/10/23_19:44:56 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
ccm[17916]: 2007/10/23_19:44:56 debug: quorum is 1
cib[17917]: 2007/10/23_19:44:56 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=1)
ccm[17916]: 2007/10/23_19:44:56 debug: delivering new membership to 2 clients: 
cib[17917]: 2007/10/23_19:44:56 debug: set_transition: CCM transition: old=(null), new=1
ccm[17916]: 2007/10/23_19:44:56 debug: client: pid =17921
cib[17917]: 2007/10/23_19:44:56 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
ccm[17916]: 2007/10/23_19:44:56 debug: client: pid =17917
cib[17917]: 2007/10/23_19:44:56 info: cib_ccm_msg_callback: PEER: prec370e
ccm[17916]: 2007/10/23_19:44:56 debug: send msg CCM_TYPE_PROTOVERSION_RESP to prec370d, status:[null]
cib[17917]: 2007/10/23_19:44:56 debug: update_cib_object: done
mgmtd[17922]: 2007/10/23_19:44:56 debug: update cib finished
heartbeat[17907]: 2007/10/23_19:44:56 WARN: 1 lost packet(s) for [prec370d] [22:24]
heartbeat[17907]: 2007/10/23_19:44:56 info: No pkts missing from prec370d!
crmd[17921]: 2007/10/23_19:44:56 notice: crmd_client_status_callback: Status update: Client prec370d/crmd now has status [offline]
crmd[17921]: 2007/10/23_19:44:56 notice: crmd_client_status_callback: Status update: Client prec370d/crmd now has status [online]
cib[17917]: 2007/10/23_19:44:56 debug: update_cib_object: done
mgmtd[17922]: 2007/10/23_19:44:56 debug: update cib finished
ccm[17916]: 2007/10/23_19:44:57 WARN: ccm_state_joined: received message with unknown cookie, just dropping
ccm[17916]: 2007/10/23_19:44:57 debug: dump current membership 0x2a959cf028
ccm[17916]: 2007/10/23_19:44:57 debug: 	leader=prec370e
ccm[17916]: 2007/10/23_19:44:57 debug: 	transition=1
ccm[17916]: 2007/10/23_19:44:57 debug: 	status=CCM_STATE_JOINED
ccm[17916]: 2007/10/23_19:44:57 debug: 	has_quorum=1
ccm[17916]: 2007/10/23_19:44:57 debug: 	nodename=prec370e bornon=1
ccm[17916]: 2007/10/23_19:44:57 debug: recv msg CCM_TYPE_ALIVE from prec370d, status:[null ptr]
ccm[17916]: 2007/10/23_19:44:57 debug: quorum plugin: majority
ccm[17916]: 2007/10/23_19:44:57 debug: cluster:linux-ha, member_count=2, member_quorum_votes=200
cib[17917]: 2007/10/23_19:44:57 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_STARTED
ccm[17916]: 2007/10/23_19:44:57 debug: total_node_count=2, total_quorum_votes=200
cib[17917]: 2007/10/23_19:44:57 info: mem_handle_event: no mbr_track info
crmd[17921]: 2007/10/23_19:44:57 info: do_started: Delaying start, CCM (0000000000100000) not connected
ccm[17916]: 2007/10/23_19:44:57 debug: send msg CCM_TYPE_MEM_LIST to cluster, status:[null]
cib[17917]: 2007/10/23_19:44:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
crmd[17921]: 2007/10/23_19:44:57 debug: register_fsa_input_adv: do_started prepended FSA input 3 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
ccm[17916]: 2007/10/23_19:44:57 debug: dump current membership 0x2a959cf028
cib[17917]: 2007/10/23_19:44:57 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
crmd[17921]: 2007/10/23_19:44:57 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
ccm[17916]: 2007/10/23_19:44:57 debug: 	leader=prec370e
cib[17917]: 2007/10/23_19:44:57 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=2)
crmd[17921]: 2007/10/23_19:44:57 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
ccm[17916]: 2007/10/23_19:44:57 debug: 	transition=2
cib[17917]: 2007/10/23_19:44:57 debug: set_transition: CCM transition: old=1, new=2
crmd[17921]: 2007/10/23_19:44:57 debug: config_query_callback: Call 4 : Parsing CIB options
ccm[17916]: 2007/10/23_19:44:57 debug: 	status=CCM_STATE_JOINED
cib[17917]: 2007/10/23_19:44:57 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[17916]: 2007/10/23_19:44:57 debug: 	has_quorum=1
cib[17917]: 2007/10/23_19:44:57 info: cib_ccm_msg_callback: PEER: prec370e
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
ccm[17916]: 2007/10/23_19:44:57 debug: 	nodename=prec370e bornon=1
cib[17917]: 2007/10/23_19:44:57 info: cib_ccm_msg_callback: PEER: prec370d
crmd[17921]: 2007/10/23_19:44:57 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
ccm[17916]: 2007/10/23_19:44:57 debug: 	nodename=prec370d bornon=2
cib[17917]: 2007/10/23_19:44:57 debug: update_cib_object: done
crmd[17921]: 2007/10/23_19:44:57 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 4 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
ccm[17916]: 2007/10/23_19:44:57 debug: quorum is 1
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
ccm[17916]: 2007/10/23_19:44:57 debug: delivering new membership to 2 clients: 
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: no mbr_track info
ccm[17916]: 2007/10/23_19:44:57 debug: client: pid =17921
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[17916]: 2007/10/23_19:44:57 debug: client: pid =17917
crmd[17921]: 2007/10/23_19:44:57 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
crmd[17921]: 2007/10/23_19:44:57 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
crmd[17921]: 2007/10/23_19:44:57 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 5 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
crmd[17921]: 2007/10/23_19:44:57 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[17921]: 2007/10/23_19:44:57 debug: do_ccm_update_cache: Updating cache after CCM event 2 (NEW MEMBERSHIP).
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: NEW MEMBERSHIP: trans=2, nodes=2, new=1, lost=0 n_idx=0, new_idx=2, old_idx=4
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: 	CURRENT: prec370e [nodeid=1, born=1]
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: 	CURRENT: prec370d [nodeid=0, born=2]
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: 	NEW:     prec370d [nodeid=0, born=2]
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[17921]: 2007/10/23_19:44:57 info: do_started: The local CRM is operational
crmd[17921]: 2007/10/23_19:44:57 debug: register_fsa_input_adv: do_started appended FSA input 6 (I_PENDING) (cause=C_CCM_CALLBACK) without data
crmd[17921]: 2007/10/23_19:44:57 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[17921]: 2007/10/23_19:44:57 debug: do_ccm_update_cache: Ignoring superceeded NEW MEMBERSHIP CCM event 1 - we had 2
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: NEW MEMBERSHIP: trans=1, nodes=1, new=1, lost=0 n_idx=0, new_idx=0, old_idx=3
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: 	CURRENT: prec370e [nodeid=1, born=1]
crmd[17921]: 2007/10/23_19:44:57 info: ccm_event_detail: 	NEW:     prec370e [nodeid=1, born=1]
crmd[17921]: 2007/10/23_19:44:57 debug: s_crmd_fsa: Processing I_PENDING: [ state=S_STARTING cause=C_CCM_CALLBACK origin=do_started ]
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[17921]: 2007/10/23_19:44:57 info: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_CCM_CALLBACK origin=do_started ]
crmd[17921]: 2007/10/23_19:44:57 info: update_dc: Set DC to <null> (<null>)
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:44:57 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_QUERY
mgmtd[17922]: 2007/10/23_19:44:57 debug: update cib finished
mgmtd[17922]: 2007/10/23_19:44:57 debug: update cib finished
ccm[17916]: 2007/10/23_19:44:57 debug: recv msg CCM_TYPE_MEM_LIST from prec370e, status:[null ptr]
ccm[17916]: 2007/10/23_19:44:57 WARN: ccm_state_joined: received message with unknown cookie, just dropping
ccm[17916]: 2007/10/23_19:44:57 debug: dump current membership 0x2a959cf028
ccm[17916]: 2007/10/23_19:44:57 debug: 	leader=prec370e
ccm[17916]: 2007/10/23_19:44:57 debug: 	transition=2
ccm[17916]: 2007/10/23_19:44:57 debug: 	status=CCM_STATE_JOINED
ccm[17916]: 2007/10/23_19:44:57 debug: 	has_quorum=1
ccm[17916]: 2007/10/23_19:44:57 debug: 	nodename=prec370e bornon=1
ccm[17916]: 2007/10/23_19:44:57 debug: 	nodename=prec370d bornon=2
crmd[17921]: 2007/10/23_19:44:58 debug: do_cl_join_query: Querying for a DC
crmd[17921]: 2007/10/23_19:44:58 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_START
crmd[17921]: 2007/10/23_19:44:58 debug: crm_timer_start: Started Election Trigger (I_DC_TIMEOUT:10000ms), src=10
crmd[17921]: 2007/10/23_19:44:58 debug: fsa_dump_inputs: Added input: 0000000000100000 (R_CCM_DATA)
crmd[17921]: 2007/10/23_19:44:58 debug: ccm_node_update_complete: Node update 9 complete
attrd[17920]: 2007/10/23_19:44:58 info: main: Starting mainloop...
crmd[17921]: 2007/10/23_19:45:08 info: crm_timer_popped: Election Trigger (I_DC_TIMEOUT) just popped!
crmd[17921]: 2007/10/23_19:45:08 debug: crm_timer_stop: Stopping Election Trigger (I_DC_TIMEOUT:10000ms), src=10
crmd[17921]: 2007/10/23_19:45:08 debug: register_fsa_input_adv: crm_timer_popped appended FSA input 7 (I_DC_TIMEOUT) (cause=C_TIMER_POPPED) without data
crmd[17921]: 2007/10/23_19:45:08 debug: s_crmd_fsa: Processing I_DC_TIMEOUT: [ state=S_PENDING cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_WARN  
crmd[17921]: 2007/10/23_19:45:08 WARN: do_log: [[FSA]] Input I_DC_TIMEOUT from crm_timer_popped() received in state (S_PENDING)
crmd[17921]: 2007/10/23_19:45:08 info: do_state_transition: State transition S_PENDING -> S_ELECTION [ input=I_DC_TIMEOUT cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[17921]: 2007/10/23_19:45:08 info: update_dc: Set DC to <null> (<null>)
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[17921]: 2007/10/23_19:45:08 debug: do_election_vote: Destroying voted hash
crmd[17921]: 2007/10/23_19:45:08 debug: crm_timer_start: Started Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[17921]: 2007/10/23_19:45:08 debug: register_fsa_input_adv: handle_request appended FSA input 8 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[17921]: 2007/10/23_19:45:08 debug: do_election_count_vote: Created voted hash
crmd[17921]: 2007/10/23_19:45:08 debug: do_election_count_vote: Election 2, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[17921]: 2007/10/23_19:45:08 info: do_election_count_vote: Updated voted hash for prec370e to vote
crmd[17921]: 2007/10/23_19:45:08 info: do_election_count_vote: Election ignore: our vote (prec370e)
crmd[17921]: 2007/10/23_19:45:08 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[17921]: 2007/10/23_19:45:08 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[17921]: 2007/10/23_19:45:09 debug: register_fsa_input_adv: handle_request appended FSA input 9 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[17921]: 2007/10/23_19:45:09 debug: do_election_count_vote: Election 2, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[17921]: 2007/10/23_19:45:09 info: do_election_count_vote: Updated voted hash for prec370d to no-vote
crmd[17921]: 2007/10/23_19:45:09 info: do_election_count_vote: Election ignore: no-vote from prec370d
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[17921]: 2007/10/23_19:45:09 debug: crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[17921]: 2007/10/23_19:45:09 debug: register_fsa_input_adv: do_election_check appended FSA input 10 (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
crmd[17921]: 2007/10/23_19:45:09 debug: do_election_check: Destroying voted hash
crmd[17921]: 2007/10/23_19:45:09 debug: s_crmd_fsa: Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[17921]: 2007/10/23_19:45:09 info: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_TE_START
crmd[17921]: 2007/10/23_19:45:09 info: start_subsystem: Starting sub-system "tengine"
crmd[17925]: 2007/10/23_19:45:09 debug: start_subsystem: Executing "/usr/lib64/heartbeat/tengine (tengine)" (pid 17925)
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_PE_START
crmd[17921]: 2007/10/23_19:45:09 info: start_subsystem: Starting sub-system "pengine"
crmd[17926]: 2007/10/23_19:45:09 debug: start_subsystem: Executing "/usr/lib64/heartbeat/pengine (pengine)" (pid 17926)
cib[17917]: 2007/10/23_19:45:09 info: cib_process_readwrite: We are now in R/W mode
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_START
crmd[17921]: 2007/10/23_19:45:09 debug: crm_timer_start: Started Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_DC_TAKEOVER
crmd[17921]: 2007/10/23_19:45:09 info: do_dc_takeover: Taking over DC status for this partition
cib[17917]: 2007/10/23_19:45:09 debug: log_data_element: cib:diff: - <cib num_updates="1"/>
mgmtd[17922]: 2007/10/23_19:45:09 debug: update cib finished
cib[17917]: 2007/10/23_19:45:09 debug: log_data_element: cib:diff: + <cib num_updates="2"/>
cib[17917]: 2007/10/23_19:45:09 debug: send_peer_reply: Sending update diff 0.1.1 -> 0.1.2
tengine[17925]: 2007/10/23_19:45:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
tengine[17925]: 2007/10/23_19:45:09 info: G_main_add_TriggerHandler: Added signal manual handler
tengine[17925]: 2007/10/23_19:45:09 info: G_main_add_TriggerHandler: Added signal manual handler
pengine[17926]: 2007/10/23_19:45:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
pengine[17926]: 2007/10/23_19:45:09 debug: main: HA_record_pengine_inputs = on
pengine[17926]: 2007/10/23_19:45:09 info: pe_init: Starting pengine
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: - <cib epoch="1" num_updates="2"/>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: + <cib epoch="2" num_updates="1">
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +   <configuration>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +     <crm_config>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +       <cluster_property_set id="cib-bootstrap-options">
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +         <attributes>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +           <nvpair id="cib-bootstrap-options-dc-version" name="dc-version" value="2.1.3-eff0a9cb1d45+ tip"/>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +         </attributes>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +       </cluster_property_set>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +     </crm_config>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: +   </configuration>
cib[17917]: 2007/10/23_19:45:09 info: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:09 debug: send_peer_reply: Sending update diff 0.1.2 -> 0.2.1
cib[17927]: 2007/10/23_19:45:09 debug: write_cib_contents: Archiving current version
mgmtd[17922]: 2007/10/23_19:45:09 debug: update cib finished
cib[17927]: 2007/10/23_19:45:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
tengine[17925]: 2007/10/23_19:45:09 debug: cib_native_signon: Connection to CIB successful
cib[17927]: 2007/10/23_19:45:09 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[17927]: 2007/10/23_19:45:09 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
cib[17927]: 2007/10/23_19:45:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
tengine[17925]: 2007/10/23_19:45:09 info: te_init: Registering TE UUID: 680ed76a-8688-4403-8e3d-b1f808edf33f
tengine[17925]: 2007/10/23_19:45:09 info: set_graph_functions: Setting custom graph functions
tengine[17925]: 2007/10/23_19:45:09 info: unpack_graph: Unpacked transition -1: 0 actions in 0 synapses
tengine[17925]: 2007/10/23_19:45:09 info: te_init: Starting tengine
cib[17927]: 2007/10/23_19:45:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
tengine[17925]: 2007/10/23_19:45:09 info: te_connect_stonith: Attempting connection to fencing daemon...
cib[17917]: 2007/10/23_19:45:09 info: cib_null_callback: Setting cib_diff_notify callbacks for tengine: on
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_OFFER_ALL
crmd[17921]: 2007/10/23_19:45:09 debug: initialize_join: join-1: Initializing join data (flag=true)
crmd[17921]: 2007/10/23_19:45:09 info: update_dc: Set DC to <null> (<null>)
crmd[17921]: 2007/10/23_19:45:09 info: join_make_offer: Making join offers based on membership 2
crmd[17921]: 2007/10/23_19:45:09 debug: join_make_offer: join-1: Sending offer to prec370d
crmd[17921]: 2007/10/23_19:45:09 debug: join_make_offer: join-1: Sending offer to prec370e
crmd[17921]: 2007/10/23_19:45:09 info: do_dc_join_offer_all: join-1: Waiting on 2 outstanding join acks
crmd[17921]: 2007/10/23_19:45:09 debug: fsa_dump_inputs: Added input: 0000000000000001 (R_THE_DC)
crmd[17921]: 2007/10/23_19:45:09 debug: fsa_dump_inputs: Added input: 0000000000000010 (R_JOIN_OK)
cib[17927]: 2007/10/23_19:45:09 debug: write_cib_contents: Verified CIB archive
crmd[17921]: 2007/10/23_19:45:09 debug: fsa_dump_inputs: Added input: 0000000000000080 (R_INVOKE_PE)
crmd[17921]: 2007/10/23_19:45:09 debug: fsa_dump_inputs: Added input: 0000000000002000 (R_PE_REQUIRED)
crmd[17921]: 2007/10/23_19:45:09 debug: fsa_dump_inputs: Added input: 0000000000004000 (R_TE_REQUIRED)
cib[17927]: 2007/10/23_19:45:09 debug: write_cib_contents: Wrote CIB to disk
cib[17927]: 2007/10/23_19:45:09 info: write_cib_contents: Wrote version 0.2.1 of the CIB to disk (digest: 58324f34cce2c0c9ed1fe02ed361a384)
cib[17927]: 2007/10/23_19:45:09 debug: write_cib_contents: Wrote digest to disk
cib[17927]: 2007/10/23_19:45:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[17927]: 2007/10/23_19:45:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[17927]: 2007/10/23_19:45:09 debug: write_cib_contents: Wrote and verified CIB
crmd[17921]: 2007/10/23_19:45:09 debug: handle_request: Raising I_JOIN_OFFER: join-1
crmd[17921]: 2007/10/23_19:45:09 debug: register_fsa_input_adv: route_message appended FSA input 11 (I_JOIN_OFFER) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:09 debug: s_crmd_fsa: Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_REQUEST
crmd[17921]: 2007/10/23_19:45:09 info: update_dc: Set DC to prec370e (2.0)
crmd[17921]: 2007/10/23_19:45:09 debug: do_cl_join_offer_respond: do_cl_join_offer_respond added action A_DC_TIMER_STOP to the FSA
crmd[17921]: 2007/10/23_19:45:09 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:10 debug: join_query_callback: Respond to join offer join-1
crmd[17921]: 2007/10/23_19:45:10 debug: join_query_callback: Acknowledging prec370e as our DC
crmd[17921]: 2007/10/23_19:45:10 debug: register_fsa_input_adv: handle_request appended FSA input 12 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:10 debug: register_fsa_input_adv: route_message appended FSA input 13 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Created voted hash
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Election 2, owner: 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6
crmd[17921]: 2007/10/23_19:45:10 info: do_election_count_vote: Election check: vote from prec370d
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Election pass: born_on
crmd[17921]: 2007/10/23_19:45:10 info: do_election_count_vote: Election won over prec370d
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Destroying voted hash
crmd[17921]: 2007/10/23_19:45:10 debug: register_fsa_input_adv: do_election_count_vote appended FSA input 14 (I_ELECTION) (cause=C_FSA_INTERNAL) without data
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_check: Ignore election check: we not in an election
crmd[17921]: 2007/10/23_19:45:10 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[17921]: 2007/10/23_19:45:10 debug: do_dc_join_filter_offer: Processing req from prec370e
crmd[17921]: 2007/10/23_19:45:10 debug: do_dc_join_filter_offer: join-1: Welcoming node prec370e (ref join_request-crmd-1193136310-8)
crmd[17921]: 2007/10/23_19:45:10 debug: do_dc_join_filter_offer: 1 nodes have been integrated into join-1
crmd[17921]: 2007/10/23_19:45:10 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[17921]: 2007/10/23_19:45:10 debug: do_dc_join_filter_offer: join-1: Still waiting on 1 outstanding offers
crmd[17921]: 2007/10/23_19:45:10 debug: s_crmd_fsa: Processing I_ELECTION: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=do_election_count_vote ]
crmd[17921]: 2007/10/23_19:45:10 info: do_state_transition: State transition S_INTEGRATION -> S_ELECTION [ input=I_ELECTION cause=C_FSA_INTERNAL origin=do_election_count_vote ]
crmd[17921]: 2007/10/23_19:45:10 info: update_dc: Set DC to <null> (<null>)
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:10 debug: crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_vote: Destroying voted hash
crmd[17921]: 2007/10/23_19:45:10 debug: crm_timer_start: Started Election Timeout (I_ELECTION_DC:120000ms), src=15
tengine[17925]: 2007/10/23_19:45:10 debug: stonithd_signon: creating connection
stonithd[17919]: 2007/10/23_19:45:10 debug: client tengine (pid=17925) succeeded to signon to stonithd.
tengine[17925]: 2007/10/23_19:45:10 debug: sending out the signon msg.
tengine[17925]: 2007/10/23_19:45:10 debug: signed on to stonithd.
tengine[17925]: 2007/10/23_19:45:10 info: te_connect_stonith: Connected
crmd[17921]: 2007/10/23_19:45:10 debug: register_fsa_input_adv: handle_request appended FSA input 15 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Created voted hash
crmd[17921]: 2007/10/23_19:45:10 debug: do_election_count_vote: Election 3, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[17921]: 2007/10/23_19:45:10 info: do_election_count_vote: Updated voted hash for prec370e to vote
crmd[17921]: 2007/10/23_19:45:10 info: do_election_count_vote: Election ignore: our vote (prec370e)
crmd[17921]: 2007/10/23_19:45:10 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[17921]: 2007/10/23_19:45:10 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[17921]: 2007/10/23_19:45:11 debug: register_fsa_input_adv: handle_request appended FSA input 16 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[17921]: 2007/10/23_19:45:11 debug: do_election_count_vote: Election 3, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[17921]: 2007/10/23_19:45:11 info: do_election_count_vote: Updated voted hash for prec370d to no-vote
crmd[17921]: 2007/10/23_19:45:11 info: do_election_count_vote: Election ignore: no-vote from prec370d
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[17921]: 2007/10/23_19:45:11 debug: crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms), src=15
crmd[17921]: 2007/10/23_19:45:11 debug: register_fsa_input_adv: do_election_check appended FSA input 17 (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
crmd[17921]: 2007/10/23_19:45:11 debug: do_election_check: Destroying voted hash
crmd[17921]: 2007/10/23_19:45:11 debug: s_crmd_fsa: Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_check ]
cib[17917]: 2007/10/23_19:45:11 info: cib_process_readwrite: We are now in R/O mode
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_LOG   
cib[17917]: 2007/10/23_19:45:11 info: cib_process_readwrite: We are now in R/W mode
crmd[17921]: 2007/10/23_19:45:11 info: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_TE_START
crmd[17921]: 2007/10/23_19:45:11 info: start_subsystem: Starting sub-system "tengine"
crmd[17921]: 2007/10/23_19:45:11 WARN: start_subsystem: Client tengine already running as pid 17925
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_PE_START
crmd[17921]: 2007/10/23_19:45:11 info: start_subsystem: Starting sub-system "pengine"
crmd[17921]: 2007/10/23_19:45:11 WARN: start_subsystem: Client pengine already running as pid 17926
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_START
crmd[17921]: 2007/10/23_19:45:11 debug: crm_timer_start: Started Integration Timer (I_INTEGRATED:180000ms), src=16
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_DC_TAKEOVER
crmd[17921]: 2007/10/23_19:45:11 info: do_dc_takeover: Taking over DC status for this partition
cib[17917]: 2007/10/23_19:45:11 debug: log_data_element: cib:diff: - <cib num_updates="1"/>
tengine[17925]: 2007/10/23_19:45:11 debug: te_update_diff: Processing diff (cib_update): 0.2.1 -> 0.2.2
cib[17917]: 2007/10/23_19:45:11 debug: log_data_element: cib:diff: + <cib num_updates="2"/>
mgmtd[17922]: 2007/10/23_19:45:11 debug: update cib finished
cib[17917]: 2007/10/23_19:45:11 debug: send_peer_reply: Sending update diff 0.2.1 -> 0.2.2
crmd[17921]: 2007/10/23_19:45:11 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_OFFER_ALL
crmd[17921]: 2007/10/23_19:45:11 debug: initialize_join: join-2: Initializing join data (flag=true)
crmd[17921]: 2007/10/23_19:45:11 info: update_dc: Set DC to <null> (<null>)
crmd[17921]: 2007/10/23_19:45:11 debug: join_make_offer: join-2: Sending offer to prec370d
crmd[17921]: 2007/10/23_19:45:11 debug: join_make_offer: join-2: Sending offer to prec370e
crmd[17921]: 2007/10/23_19:45:11 info: do_dc_join_offer_all: join-2: Waiting on 2 outstanding join acks
cib[17917]: 2007/10/23_19:45:11 debug: log_data_element: cib:diff: - <cib num_updates="2"/>
mgmtd[17922]: 2007/10/23_19:45:11 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:11 debug: te_update_diff: Processing diff (cib_modify): 0.2.2 -> 0.2.3
cib[17917]: 2007/10/23_19:45:11 debug: log_data_element: cib:diff: + <cib num_updates="3"/>
cib[17917]: 2007/10/23_19:45:11 debug: send_peer_reply: Sending update diff 0.2.2 -> 0.2.3
crmd[17921]: 2007/10/23_19:45:12 debug: handle_request: Raising I_JOIN_OFFER: join-2
crmd[17921]: 2007/10/23_19:45:12 debug: register_fsa_input_adv: route_message appended FSA input 18 (I_JOIN_OFFER) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:12 debug: s_crmd_fsa: Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:12 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_REQUEST
crmd[17921]: 2007/10/23_19:45:12 info: update_dc: Set DC to prec370e (2.0)
crmd[17921]: 2007/10/23_19:45:12 debug: do_cl_join_offer_respond: do_cl_join_offer_respond added action A_DC_TIMER_STOP to the FSA
crmd[17921]: 2007/10/23_19:45:12 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:12 debug: join_query_callback: Respond to join offer join-2
crmd[17921]: 2007/10/23_19:45:12 debug: join_query_callback: Acknowledging prec370e as our DC
crmd[17921]: 2007/10/23_19:45:12 debug: register_fsa_input_adv: route_message appended FSA input 19 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:12 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:12 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[17921]: 2007/10/23_19:45:12 debug: do_dc_join_filter_offer: Processing req from prec370e
crmd[17921]: 2007/10/23_19:45:12 debug: do_dc_join_filter_offer: join-2: Welcoming node prec370e (ref join_request-crmd-1193136312-12)
crmd[17921]: 2007/10/23_19:45:12 debug: do_dc_join_filter_offer: 1 nodes have been integrated into join-2
crmd[17921]: 2007/10/23_19:45:12 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[17921]: 2007/10/23_19:45:12 debug: do_dc_join_filter_offer: join-2: Still waiting on 1 outstanding offers
crmd[17921]: 2007/10/23_19:45:13 debug: register_fsa_input_adv: route_message appended FSA input 20 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:13 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[17921]: 2007/10/23_19:45:13 debug: do_dc_join_filter_offer: Processing req from prec370d
crmd[17921]: 2007/10/23_19:45:13 debug: do_dc_join_filter_offer: join-2: Welcoming node prec370d (ref join_request-crmd-1193136312-5)
crmd[17921]: 2007/10/23_19:45:13 debug: do_dc_join_filter_offer: 2 nodes have been integrated into join-2
crmd[17921]: 2007/10/23_19:45:13 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[17921]: 2007/10/23_19:45:13 debug: check_join_state: join-2: Integration of 2 peers complete: do_dc_join_filter_offer
crmd[17921]: 2007/10/23_19:45:13 debug: register_fsa_input_adv: check_join_state prepended FSA input 21 (I_INTEGRATED) (cause=C_FSA_INTERNAL) without data
crmd[17921]: 2007/10/23_19:45:13 debug: s_crmd_fsa: Processing I_INTEGRATED: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[17921]: 2007/10/23_19:45:13 info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[17921]: 2007/10/23_19:45:13 info: do_state_transition: All 2 cluster nodes responded to the join offer.
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[17917]: 2007/10/23_19:45:13 info: sync_our_cib: Syncing CIB to all peers
crmd[17921]: 2007/10/23_19:45:13 debug: crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms), src=16
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_START
crmd[17921]: 2007/10/23_19:45:13 debug: crm_timer_start: Started Finalization Timer (I_ELECTION:600000ms), src=17
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_FINALIZE
crmd[17921]: 2007/10/23_19:45:13 debug: do_dc_join_finalize: Finializing join-2 for 2 clients
crmd[17921]: 2007/10/23_19:45:13 info: update_attrd: Connecting to attrd...
crmd[17921]: 2007/10/23_19:45:13 debug: update_attrd: sent attrd refresh
attrd[17920]: 2007/10/23_19:45:13 info: attrd_local_callback: Sending full refresh
crmd[17921]: 2007/10/23_19:45:13 debug: check_join_state: Invoked by do_dc_join_finalize in state: S_FINALIZE_JOIN
crmd[17921]: 2007/10/23_19:45:13 debug: check_join_state: join-2: Still waiting on 2 integrated nodes
crmd[17921]: 2007/10/23_19:45:13 debug: finalize_join: Notifying 2 clients of join-2 results
crmd[17921]: 2007/10/23_19:45:13 debug: finalize_join_for: join-2: ACK'ing join request from prec370d, state member
crmd[17921]: 2007/10/23_19:45:13 debug: finalize_join_for: join-2: ACK'ing join request from prec370e, state member
crmd[17921]: 2007/10/23_19:45:13 debug: fsa_dump_inputs: Added input: 0000000000020000 (R_HAVE_CIB)
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: - <cib num_updates="3" generated="false"/>
mgmtd[17922]: 2007/10/23_19:45:13 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:13 debug: te_update_diff: Processing diff (cib_update): 0.2.3 -> 0.2.4
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: + <cib num_updates="4" generated="true" dc_uuid="9d9ca527-cea9-470c-9e03-e49fe5630bba"/>
cib[17917]: 2007/10/23_19:45:13 debug: send_peer_reply: Sending update diff 0.2.3 -> 0.2.4
tengine[17925]: 2007/10/23_19:45:13 debug: te_update_diff: Processing diff (cib_update): 0.2.4 -> 0.2.5
mgmtd[17922]: 2007/10/23_19:45:13 debug: update cib finished
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: - <cib num_updates="4"/>
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: + <cib num_updates="5"/>
cib[17917]: 2007/10/23_19:45:13 debug: send_peer_reply: Sending update diff 0.2.4 -> 0.2.5
mgmtd[17922]: 2007/10/23_19:45:13 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:13 debug: te_update_diff: Processing diff (cib_update): 0.2.5 -> 0.2.6
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: - <cib num_updates="5"/>
cib[17917]: 2007/10/23_19:45:13 debug: log_data_element: cib:diff: + <cib num_updates="6"/>
cib[17917]: 2007/10/23_19:45:13 debug: send_peer_reply: Sending update diff 0.2.5 -> 0.2.6
crmd[17921]: 2007/10/23_19:45:13 debug: handle_request: Raising I_JOIN_RESULT: join-2
crmd[17921]: 2007/10/23_19:45:13 debug: register_fsa_input_adv: route_message appended FSA input 22 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:13 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[17921]: 2007/10/23_19:45:13 info: update_dc: Set DC to prec370e (2.0)
crmd[17921]: 2007/10/23_19:45:13 debug: do_cl_join_finalize_respond: Confirming join join-2: join_ack_nack
crmd[17921]: 2007/10/23_19:45:13 debug: do_cl_join_finalize_respond: join-2: Join complete.  Sending local LRM status.
crmd[17921]: 2007/10/23_19:45:13 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[17921]: 2007/10/23_19:45:13 debug: do_dc_join_ack: Ignoring op=join_ack_nack message
crmd[17921]: 2007/10/23_19:45:14 debug: register_fsa_input_adv: route_message appended FSA input 23 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:14 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[17921]: 2007/10/23_19:45:14 info: do_dc_join_ack: join-2: Updating node state to member for prec370e
crmd[17921]: 2007/10/23_19:45:14 debug: do_dc_join_ack: join-2: Registered callback for LRM update 27
cib[17917]: 2007/10/23_19:45:14 debug: update_cib_object: done
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: - <cib num_updates="6"/>
crmd[17921]: 2007/10/23_19:45:14 debug: join_update_complete_callback: Join update 27 complete
tengine[17925]: 2007/10/23_19:45:14 debug: te_update_diff: Processing diff (cib_update): 0.2.6 -> 0.2.7
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + <cib num_updates="7">
mgmtd[17922]: 2007/10/23_19:45:14 debug: update cib finished
crmd[17921]: 2007/10/23_19:45:14 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   <status>
crmd[17921]: 2007/10/23_19:45:14 debug: check_join_state: join-2: Still waiting on 1 confirmations
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     <node_state ha="active" join="member" expected="member" id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         <lrm_resources/>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:14 debug: send_peer_reply: Sending update diff 0.2.6 -> 0.2.7
crmd[17921]: 2007/10/23_19:45:14 debug: register_fsa_input_adv: route_message appended FSA input 24 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:14 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[17921]: 2007/10/23_19:45:14 info: do_dc_join_ack: join-2: Updating node state to member for prec370d
cib[17917]: 2007/10/23_19:45:14 debug: update_cib_object: done
crmd[17921]: 2007/10/23_19:45:14 debug: do_dc_join_ack: join-2: Registered callback for LRM update 28
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: - <cib num_updates="7"/>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + <cib num_updates="8">
tengine[17925]: 2007/10/23_19:45:14 debug: te_update_diff: Processing diff (cib_update): 0.2.7 -> 0.2.8
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   <status>
mgmtd[17922]: 2007/10/23_19:45:14 debug: update cib finished
crmd[17921]: 2007/10/23_19:45:14 debug: join_update_complete_callback: Join update 28 complete
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     <node_state ha="active" join="member" expected="member" id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:14 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:14 debug: check_join_state: join-2 complete: join_update_complete_callback
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         <lrm_resources/>
crmd[17921]: 2007/10/23_19:45:14 debug: register_fsa_input_adv: check_join_state appended FSA input 25 (I_FINALIZED) (cause=C_FSA_INTERNAL) without data
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       </lrm>
crmd[17921]: 2007/10/23_19:45:14 debug: s_crmd_fsa: Processing I_FINALIZED: [ state=S_FINALIZE_JOIN cause=C_FSA_INTERNAL origin=check_join_state ]
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     </node_state>
crmd[17921]: 2007/10/23_19:45:14 info: do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ]
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   </status>
crmd[17921]: 2007/10/23_19:45:14 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + </cib>
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[17917]: 2007/10/23_19:45:14 debug: send_peer_reply: Sending update diff 0.2.7 -> 0.2.8
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:14 debug: crm_timer_stop: Stopping Finalization Timer (I_ELECTION:600000ms), src=17
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_TE_CANCEL
crmd[17921]: 2007/10/23_19:45:14 debug: do_te_invoke: Cancelling the active Transition
crmd[17921]: 2007/10/23_19:45:14 debug: handle_request: Transition cancelled: te_abort/Peer Cancelled
tengine[17925]: 2007/10/23_19:45:14 info: update_abort_priority: Abort priority upgraded to 1000000
crmd[17921]: 2007/10/23_19:45:14 debug: register_fsa_input_adv: route_message appended FSA input 26 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[17925]: 2007/10/23_19:45:14 info: update_abort_priority: 'DC Takeover' abort superceeded
crmd[17921]: 2007/10/23_19:45:14 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:14 debug: abort_transition_graph: process_te_message:279 - Triggered graph processing : Peer Cancelled
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
tengine[17925]: 2007/10/23_19:45:14 debug: notify_crmd: Transition -1 status: te_abort - Peer Cancelled
crmd[17921]: 2007/10/23_19:45:14 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
tengine[17925]: 2007/10/23_19:45:14 debug: print_graph: ## Empty transition graph ##
crmd[17921]: 2007/10/23_19:45:14 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1193136314-17
pengine[17926]: 2007/10/23_19:45:14 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[17926]: 2007/10/23_19:45:14 debug: unpack_config: Default action timeout: 120s
pengine[17926]: 2007/10/23_19:45:14 debug: unpack_config: Default stickiness: 1000000
pengine[17926]: 2007/10/23_19:45:14 debug: unpack_config: Default failure stickiness: -1000000
pengine[17926]: 2007/10/23_19:45:14 debug: unpack_config: STONITH of failed nodes is disabled
pengine[17926]: 2007/10/23_19:45:14 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[17926]: 2007/10/23_19:45:14 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[17926]: 2007/10/23_19:45:14 info: determine_online_status: Node prec370e is online
pengine[17926]: 2007/10/23_19:45:14 info: determine_online_status: Node prec370d is online
pengine[17926]: 2007/10/23_19:45:14 notice: group_print: Resource Group: grpDummy
pengine[17926]: 2007/10/23_19:45:14 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:14 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:14 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[17926]: 2007/10/23_19:45:14 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[17926]: 2007/10/23_19:45:14 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[17926]: 2007/10/23_19:45:14 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 300
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[17926]: 2007/10/23_19:45:14 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[17926]: 2007/10/23_19:45:14 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[17926]: 2007/10/23_19:45:14 debug: native_assign_node: Assigning prec370e to prmDummyB
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 notice: StartRsc:  prec370e	Start prmDummyA
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 notice: RecurringOp: prec370e	   prmDummyA_monitor_10000
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 notice: StartRsc:  prec370e	Start prmDummyB
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 notice: RecurringOp: prec370e	   prmDummyB_monitor_10000
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:14 debug: update_action:       Ignoring implies left - prmDummyB already stopped
pengine[17926]: 2007/10/23_19:45:14 debug: get_last_sequence: Series file /var/lib/heartbeat/pengine/pe-input.last does not exist
pengine[17926]: 2007/10/23_19:45:14 info: process_pe_message: Transition 0: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-0.bz2
pengine[17926]: 2007/10/23_19:45:14 info: process_pe_message: Configuration ERRORs found during PE processing.  Please run "crm_verify -L" to identify issues.
crmd[17921]: 2007/10/23_19:45:14 debug: register_fsa_input_adv: route_message appended FSA input 27 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:14 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[17921]: 2007/10/23_19:45:14 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:14 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
crmd[17921]: 2007/10/23_19:45:14 debug: do_te_invoke: Starting a transition
tengine[17925]: 2007/10/23_19:45:14 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-0.bz2
tengine[17925]: 2007/10/23_19:45:14 info: unpack_graph: Unpacked transition 0: 13 actions in 13 synapses
tengine[17925]: 2007/10/23_19:45:14 debug: initiate_action: Action 3: Increasing IDLE timer to 240000
tengine[17925]: 2007/10/23_19:45:14 info: send_rsc_command: Initiating action 3: prmDummyA_monitor_0 on prec370e
tengine[17925]: 2007/10/23_19:45:14 debug: send_rsc_command: Action 3: Increasing transition 0 timeout to 360000 (2*120000 + 120000)
tengine[17925]: 2007/10/23_19:45:14 info: send_rsc_command: Initiating action 6: prmDummyA_monitor_0 on prec370d
tengine[17925]: 2007/10/23_19:45:14 info: send_rsc_command: Initiating action 4: prmDummyB_monitor_0 on prec370e
tengine[17925]: 2007/10/23_19:45:14 info: send_rsc_command: Initiating action 7: prmDummyB_monitor_0 on prec370d
tengine[17925]: 2007/10/23_19:45:14 debug: run_graph: Transition 0: (Complete=0, Pending=0, Fired=4, Skipped=0, Incomplete=9)
crmd[17921]: 2007/10/23_19:45:14 debug: get_lrm_resource: Adding rsc prmDummyA before operation
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_add_rsc:client [17921] adds resource prmDummyA
crmd[17921]: 2007/10/23_19:45:14 info: do_lrm_rsc_op: Performing op=prmDummyA_monitor_0 key=3:0:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_perform_op: add an operation operation monitor[2] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[17918]: 2007/10/23_19:45:14 info: rsc:prmDummyA: monitor
crmd[17921]: 2007/10/23_19:45:14 debug: do_lrm_rsc_op: Recording pending op: 2 - prmDummyA_monitor_0 prmDummyA:2
crmd[17921]: 2007/10/23_19:45:14 debug: get_lrm_resource: Adding rsc prmDummyB before operation
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_add_rsc:client [17921] adds resource prmDummyB
crmd[17921]: 2007/10/23_19:45:14 info: do_lrm_rsc_op: Performing op=prmDummyB_monitor_0 key=4:0:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
lrmd[17918]: 2007/10/23_19:45:14 debug: on_msg_perform_op: add an operation operation monitor[3] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[17918]: 2007/10/23_19:45:14 info: rsc:prmDummyB: monitor
crmd[17921]: 2007/10/23_19:45:14 debug: do_lrm_rsc_op: Recording pending op: 3 - prmDummyB_monitor_0 prmDummyB:3
Dummy[17928][17940]: 2007/10/23_19:45:14 DEBUG: prmDummyA monitor : 7
lrmd[17918]: 2007/10/23_19:45:14 WARN: Managed prmDummyA:monitor process 17928 exited with return code 7.
Dummy[17933][17941]: 2007/10/23_19:45:14 DEBUG: prmDummyB monitor : 7
crmd[17921]: 2007/10/23_19:45:14 info: process_lrm_event: LRM operation prmDummyA_monitor_0 (call=2, rc=7) complete 
lrmd[17918]: 2007/10/23_19:45:14 WARN: Managed prmDummyB:monitor process 17933 exited with return code 7.
crmd[17921]: 2007/10/23_19:45:14 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_monitor_0 (0:7;3:0:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:45:14 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:45:14 debug: do_update_resource: Sent resource state update message: 30
crmd[17921]: 2007/10/23_19:45:14 debug: process_lrm_event: Op prmDummyA_monitor_0 (call=2): Confirmed
crmd[17921]: 2007/10/23_19:45:14 info: process_lrm_event: LRM operation prmDummyB_monitor_0 (call=3, rc=7) complete 
crmd[17921]: 2007/10/23_19:45:14 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_monitor_0 (0:7;4:0:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:45:14 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:45:14 debug: do_update_resource: Sent resource state update message: 31
crmd[17921]: 2007/10/23_19:45:14 debug: process_lrm_event: Op prmDummyB_monitor_0 (call=3): Confirmed
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: - <cib num_updates="8"/>
mgmtd[17922]: 2007/10/23_19:45:14 debug: update cib finished
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + <cib num_updates="9">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA" type="Dummy" class="ocf" provider="heartbeat">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyA_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="3:0:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;3:0:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="2" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   </status>
tengine[17925]: 2007/10/23_19:45:14 debug: te_update_diff: Processing diff (cib_update): 0.2.8 -> 0.2.9
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + </cib>
tengine[17925]: 2007/10/23_19:45:14 info: match_graph_event: Action prmDummyA_monitor_0 (3) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:14 debug: send_peer_reply: Sending update diff 0.2.8 -> 0.2.9
tengine[17925]: 2007/10/23_19:45:14 debug: run_graph: Transition 0: (Complete=1, Pending=3, Fired=0, Skipped=0, Incomplete=9)
crmd[17921]: 2007/10/23_19:45:14 debug: cib_rsc_callback: Resource update 30 complete: rc=0
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: - <cib num_updates="9"/>
mgmtd[17922]: 2007/10/23_19:45:14 debug: update cib finished
crmd[17921]: 2007/10/23_19:45:14 debug: cib_rsc_callback: Resource update 31 complete: rc=0
tengine[17925]: 2007/10/23_19:45:14 debug: te_update_diff: Processing diff (cib_update): 0.2.9 -> 0.2.10
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + <cib num_updates="10">
tengine[17925]: 2007/10/23_19:45:14 info: match_graph_event: Action prmDummyB_monitor_0 (4) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:45:14 info: send_rsc_command: Initiating action 2: probe_complete on prec370e
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:14 debug: send_rsc_command: Skipping wait for 2
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:14 debug: run_graph: Transition 0: (Complete=2, Pending=2, Fired=1, Skipped=0, Incomplete=8)
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[17925]: 2007/10/23_19:45:14 debug: run_graph: Transition 0: (Complete=3, Pending=2, Fired=0, Skipped=0, Incomplete=8)
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB" type="Dummy" class="ocf" provider="heartbeat">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyB_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="4:0:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;4:0:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="3" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:14 debug: send_peer_reply: Sending update diff 0.2.9 -> 0.2.10
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: - <cib num_updates="10"/>
mgmtd[17922]: 2007/10/23_19:45:14 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:14 debug: te_update_diff: Processing diff (cib_modify): 0.2.10 -> 0.2.11
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + <cib num_updates="11">
tengine[17925]: 2007/10/23_19:45:14 info: extract_event: Aborting on transient_attributes changes for 9d9ca527-cea9-470c-9e03-e49fe5630bba
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:45:14 info: update_abort_priority: Abort priority upgraded to 1000000
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:14 info: update_abort_priority: Abort action 0 superceeded by 2
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       <transient_attributes id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:14 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         <instance_attributes id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           <attributes>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +             <nvpair id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba-probe_complete" name="probe_complete" value="true"/>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause     <attributes>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +           </attributes>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba-probe_complete" name="probe_complete" value="true"/>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +         </instance_attributes>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +       </transient_attributes>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +     </node_state>
tengine[17925]: 2007/10/23_19:45:14 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: +   </status>
tengine[17925]: 2007/10/23_19:45:14 debug: run_graph: Transition 0: (Complete=3, Pending=2, Fired=0, Skipped=7, Incomplete=1)
cib[17917]: 2007/10/23_19:45:14 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:14 debug: send_peer_reply: Sending update diff 0.2.10 -> 0.2.11
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="11"/>
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.11 -> 0.2.12
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="12">
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyA_monitor_0 (6) confirmed on prec370d (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 0: (Complete=4, Pending=1, Fired=0, Skipped=7, Incomplete=1)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA" type="Dummy" class="ocf" provider="heartbeat">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyA_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="6:0:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;6:0:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="2" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.11 -> 0.2.12
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="12"/>
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.12 -> 0.2.13
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="13">
crmd[17921]: 2007/10/23_19:45:15 debug: handle_request: Transition cancelled: te_abort/transient_attributes
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyB_monitor_0 (7) confirmed on prec370d (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
crmd[17921]: 2007/10/23_19:45:15 debug: register_fsa_input_adv: route_message appended FSA input 28 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 5: probe_complete on prec370d
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:15 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:15 debug: send_rsc_command: Skipping wait for 5
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:15 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 0: (Complete=5, Pending=0, Fired=1, Skipped=7, Incomplete=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
crmd[17921]: 2007/10/23_19:45:15 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
tengine[17925]: 2007/10/23_19:45:15 info: run_graph: ====================================================
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB" type="Dummy" class="ocf" provider="heartbeat">
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:15 notice: run_graph: Transition 0: (Complete=6, Pending=0, Fired=0, Skipped=7, Incomplete=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyB_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="7:0:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;7:0:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="3" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:15 debug: notify_crmd: Transition 0 status: te_abort - transient_attributes
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
crmd[17921]: 2007/10/23_19:45:15 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.12 -> 0.2.13
crmd[17921]: 2007/10/23_19:45:15 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1193136315-19
pengine[17926]: 2007/10/23_19:45:15 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[17926]: 2007/10/23_19:45:15 debug: unpack_config: Default action timeout: 120s
pengine[17926]: 2007/10/23_19:45:15 debug: unpack_config: Default stickiness: 1000000
pengine[17926]: 2007/10/23_19:45:15 debug: unpack_config: Default failure stickiness: -1000000
pengine[17926]: 2007/10/23_19:45:15 debug: unpack_config: STONITH of failed nodes is disabled
pengine[17926]: 2007/10/23_19:45:15 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[17926]: 2007/10/23_19:45:15 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[17926]: 2007/10/23_19:45:15 info: determine_online_status: Node prec370e is online
pengine[17926]: 2007/10/23_19:45:15 info: determine_online_status: Node prec370d is online
pengine[17926]: 2007/10/23_19:45:15 notice: group_print: Resource Group: grpDummy
pengine[17926]: 2007/10/23_19:45:15 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:15 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:15 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[17926]: 2007/10/23_19:45:15 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[17926]: 2007/10/23_19:45:15 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[17926]: 2007/10/23_19:45:15 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 300
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[17926]: 2007/10/23_19:45:15 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[17926]: 2007/10/23_19:45:15 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[17926]: 2007/10/23_19:45:15 debug: native_assign_node: Assigning prec370e to prmDummyB
crmd[17921]: 2007/10/23_19:45:15 debug: register_fsa_input_adv: route_message appended FSA input 29 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:15 notice: StartRsc:  prec370e	Start prmDummyA
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:15 notice: RecurringOp: prec370e	   prmDummyA_monitor_10000
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:15 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[17926]: 2007/10/23_19:45:15 notice: StartRsc:  prec370e	Start prmDummyB
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_LOG   
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:15 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
pengine[17926]: 2007/10/23_19:45:15 notice: RecurringOp: prec370e	   prmDummyB_monitor_10000
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
pengine[17926]: 2007/10/23_19:45:15 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
pengine[17926]: 2007/10/23_19:45:15 debug: update_action:       Ignoring implies left - prmDummyB already stopped
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
crmd[17921]: 2007/10/23_19:45:15 debug: do_te_invoke: Starting a transition
tengine[17925]: 2007/10/23_19:45:15 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-1.bz2
tengine[17925]: 2007/10/23_19:45:15 info: unpack_graph: Unpacked transition 1: 7 actions in 7 synapses
tengine[17925]: 2007/10/23_19:45:15 debug: initiate_action: Action 9: Increasing IDLE timer to 240000
tengine[17925]: 2007/10/23_19:45:15 info: te_pseudo_action: Pseudo action 9 fired and confirmed
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 5: prmDummyA_start_0 on prec370e
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 3: probe_complete on prec370d
tengine[17925]: 2007/10/23_19:45:15 debug: send_rsc_command: Skipping wait for 3
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=0, Pending=0, Fired=3, Skipped=0, Incomplete=4)
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=4)
crmd[17921]: 2007/10/23_19:45:15 info: do_lrm_rsc_op: Performing op=prmDummyA_start_0 key=5:1:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op: add an operation operation start[4] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_id=[opDummyAStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
lrmd[17918]: 2007/10/23_19:45:15 info: rsc:prmDummyA: start
crmd[17921]: 2007/10/23_19:45:15 debug: do_lrm_rsc_op: Recording pending op: 4 - prmDummyA_start_0 prmDummyA:4
pengine[17926]: 2007/10/23_19:45:15 info: process_pe_message: Transition 1: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-1.bz2
pengine[17926]: 2007/10/23_19:45:15 info: process_pe_message: Configuration ERRORs found during PE processing.  Please run "crm_verify -L" to identify issues.
Dummy[17942][17949]: 2007/10/23_19:45:15 DEBUG: prmDummyA start : 0
lrmd[17918]: 2007/10/23_19:45:15 info: Managed prmDummyA:start process 17942 exited with return code 0.
crmd[17921]: 2007/10/23_19:45:15 info: process_lrm_event: LRM operation prmDummyA_start_0 (call=4, rc=0) complete 
crmd[17921]: 2007/10/23_19:45:15 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_start_0 (0:0;5:1:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:45:15 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:45:15 debug: get_rsc_metadata: Retreiving metadata for Dummy::ocf:heartbeat
crmd[17921]: 2007/10/23_19:45:15 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[17921]: 2007/10/23_19:45:15 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[17921]: 2007/10/23_19:45:15 debug: do_update_resource: Sent resource state update message: 35
crmd[17921]: 2007/10/23_19:45:15 debug: process_lrm_event: Op prmDummyA_start_0 (call=4): Confirmed
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="13"/>
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
crmd[17921]: 2007/10/23_19:45:15 debug: cib_rsc_callback: Resource update 35 complete: rc=0
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.13 -> 0.2.14
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="14">
crmd[17921]: 2007/10/23_19:45:15 info: do_lrm_rsc_op: Performing op=prmDummyA_monitor_10000 key=6:1:680ed76a-8688-4403-8e3d-b1f808edf33f)
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyA_start_0 (5) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op: add an operation operation monitor[5] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyAMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 6: prmDummyA_monitor_10000 on prec370e
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 7: prmDummyB_start_0 on prec370e
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=3, Pending=0, Fired=2, Skipped=0, Incomplete=2)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyA_start_0" operation="start" crm-debug-origin="do_update_resource" transition_key="5:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;5:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="4" crm_feature_set="2.0" rc_code="0" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8" op_force_restart=" state " op_restart_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.13 -> 0.2.14
crmd[17921]: 2007/10/23_19:45:15 debug: do_lrm_rsc_op: Recording pending op: 5 - prmDummyA_monitor_10000 prmDummyA:5
crmd[17921]: 2007/10/23_19:45:15 info: do_lrm_rsc_op: Performing op=prmDummyB_start_0 key=7:1:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op: add an operation operation start[6] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_id=[opDummyBStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
crmd[17921]: 2007/10/23_19:45:15 debug: do_lrm_rsc_op: Recording pending op: 6 - prmDummyB_start_0 prmDummyB:6
lrmd[17918]: 2007/10/23_19:45:15 info: rsc:prmDummyB: start
Dummy[17957][17969]: 2007/10/23_19:45:15 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:45:15 info: Managed prmDummyA:monitor process 17957 exited with return code 0.
Dummy[17958][17971]: 2007/10/23_19:45:15 DEBUG: prmDummyB start : 0
lrmd[17918]: 2007/10/23_19:45:15 info: Managed prmDummyB:start process 17958 exited with return code 0.
crmd[17921]: 2007/10/23_19:45:15 info: process_lrm_event: LRM operation prmDummyA_monitor_10000 (call=5, rc=0) complete 
crmd[17921]: 2007/10/23_19:45:15 debug: do_update_resource: Sent resource state update message: 36
crmd[17921]: 2007/10/23_19:45:15 info: process_lrm_event: LRM operation prmDummyB_start_0 (call=6, rc=0) complete 
crmd[17921]: 2007/10/23_19:45:15 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_start_0 (0:0;7:1:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:45:15 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:45:15 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[17921]: 2007/10/23_19:45:15 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[17921]: 2007/10/23_19:45:15 debug: do_update_resource: Sent resource state update message: 37
crmd[17921]: 2007/10/23_19:45:15 debug: process_lrm_event: Op prmDummyB_start_0 (call=6): Confirmed
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.14 -> 0.2.15
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="14"/>
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyA_monitor_10000 (6) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="15">
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=4, Pending=1, Fired=0, Skipped=0, Incomplete=2)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyA_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="6:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;6:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="5" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.14 -> 0.2.15
crmd[17921]: 2007/10/23_19:45:15 debug: cib_rsc_callback: Resource update 36 complete: rc=0
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="15"/>
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.15 -> 0.2.16
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="16">
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyB_start_0 (7) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
crmd[17921]: 2007/10/23_19:45:15 debug: cib_rsc_callback: Resource update 37 complete: rc=0
tengine[17925]: 2007/10/23_19:45:15 info: te_pseudo_action: Pseudo action 10 fired and confirmed
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:15 info: send_rsc_command: Initiating action 8: prmDummyB_monitor_10000 on prec370e
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=5, Pending=0, Fired=2, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: Transition 1: (Complete=6, Pending=1, Fired=0, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyB_start_0" operation="start" crm-debug-origin="do_update_resource" transition_key="7:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;7:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="6" crm_feature_set="2.0" rc_code="0" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8" op_force_restart=" state " op_restart_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.15 -> 0.2.16
crmd[17921]: 2007/10/23_19:45:15 info: do_lrm_rsc_op: Performing op=prmDummyB_monitor_10000 key=8:1:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:45:15 debug: on_msg_perform_op: add an operation operation monitor[7] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyBMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
crmd[17921]: 2007/10/23_19:45:15 debug: do_lrm_rsc_op: Recording pending op: 7 - prmDummyB_monitor_10000 prmDummyB:7
Dummy[17972][17978]: 2007/10/23_19:45:15 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:45:15 info: Managed prmDummyB:monitor process 17972 exited with return code 0.
crmd[17921]: 2007/10/23_19:45:15 info: process_lrm_event: LRM operation prmDummyB_monitor_10000 (call=7, rc=0) complete 
crmd[17921]: 2007/10/23_19:45:15 debug: do_update_resource: Sent resource state update message: 38
mgmtd[17922]: 2007/10/23_19:45:15 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:15 debug: te_update_diff: Processing diff (cib_update): 0.2.16 -> 0.2.17
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: - <cib num_updates="16"/>
tengine[17925]: 2007/10/23_19:45:15 info: match_graph_event: Action prmDummyB_monitor_10000 (8) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + <cib num_updates="17">
tengine[17925]: 2007/10/23_19:45:15 debug: run_graph: ====================================================
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:45:15 info: run_graph: Transition 1: (Complete=7, Pending=0, Fired=0, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:45:15 info: notify_crmd: Transition 1 status: te_complete - <null>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
crmd[17921]: 2007/10/23_19:45:15 debug: cib_rsc_callback: Resource update 38 complete: rc=0
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyB_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="8:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;8:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="7" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
crmd[17921]: 2007/10/23_19:45:15 debug: handle_request: Transition complete: te_complete/(null)
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +           </lrm_resource>
crmd[17921]: 2007/10/23_19:45:15 debug: register_fsa_input_adv: route_message appended FSA input 30 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[17921]: 2007/10/23_19:45:15 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +       </lrm>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_LOG   
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +     </node_state>
crmd[17921]: 2007/10/23_19:45:15 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: +   </status>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[17917]: 2007/10/23_19:45:15 debug: log_data_element: cib:diff: + </cib>
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[17917]: 2007/10/23_19:45:15 debug: send_peer_reply: Sending update diff 0.2.16 -> 0.2.17
crmd[17921]: 2007/10/23_19:45:15 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
heartbeat[17907]: 2007/10/23_19:45:16 debug: rexmit request from node prec370d for msg(71-71)
heartbeat[17907]: 2007/10/23_19:45:16 info: Retransmitting pkt 71
heartbeat[17907]: 2007/10/23_19:45:16 info: msg size =1659, type=cib
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: - <cib num_updates="17"/>
crmd[17921]: 2007/10/23_19:45:16 debug: handle_request: Transition cancelled: te_abort/transient_attributes
tengine[17925]: 2007/10/23_19:45:16 debug: te_update_diff: Processing diff (cib_modify): 0.2.17 -> 0.2.18
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: + <cib num_updates="18">
mgmtd[17922]: 2007/10/23_19:45:16 debug: update cib finished
crmd[17921]: 2007/10/23_19:45:16 debug: register_fsa_input_adv: route_message appended FSA input 31 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[17925]: 2007/10/23_19:45:16 info: extract_event: Aborting on transient_attributes changes for 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +   <status>
crmd[17921]: 2007/10/23_19:45:16 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:16 info: update_abort_priority: Abort priority upgraded to 1000000
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:16 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:16 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +       <transient_attributes id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:16 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +         <instance_attributes id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +           <attributes>
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause     <attributes>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +             <nvpair id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6-probe_complete" name="probe_complete" value="true"/>
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6-probe_complete" name="probe_complete" value="true"/>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +           </attributes>
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +         </instance_attributes>
crmd[17921]: 2007/10/23_19:45:16 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +       </transient_attributes>
tengine[17925]: 2007/10/23_19:45:16 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +     </node_state>
tengine[17925]: 2007/10/23_19:45:16 debug: notify_crmd: Transition 1 status: te_abort - transient_attributes
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:45:16 debug: send_peer_reply: Sending update diff 0.2.17 -> 0.2.18
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: - <cib num_updates="18"/>
cib[17917]: 2007/10/23_19:45:16 debug: log_data_element: cib:diff: + <cib num_updates="19"/>
cib[17917]: 2007/10/23_19:45:16 debug: send_peer_reply: Sending update diff 0.2.18 -> 0.2.19
mgmtd[17922]: 2007/10/23_19:45:16 debug: update cib finished
tengine[17925]: 2007/10/23_19:45:16 debug: te_update_diff: Processing diff (cib_modify): 0.2.18 -> 0.2.19
crmd[17921]: 2007/10/23_19:45:16 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1193136316-21
pengine[17926]: 2007/10/23_19:45:16 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[17926]: 2007/10/23_19:45:16 debug: unpack_config: Default action timeout: 120s
pengine[17926]: 2007/10/23_19:45:16 debug: unpack_config: Default stickiness: 1000000
pengine[17926]: 2007/10/23_19:45:16 debug: unpack_config: Default failure stickiness: -1000000
pengine[17926]: 2007/10/23_19:45:16 debug: unpack_config: STONITH of failed nodes is disabled
pengine[17926]: 2007/10/23_19:45:16 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[17926]: 2007/10/23_19:45:16 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[17926]: 2007/10/23_19:45:16 info: determine_online_status: Node prec370e is online
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 info: determine_online_status: Node prec370d is online
pengine[17926]: 2007/10/23_19:45:16 notice: group_print: Resource Group: grpDummy
pengine[17926]: 2007/10/23_19:45:16 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:45:16 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:45:16 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[17926]: 2007/10/23_19:45:16 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[17926]: 2007/10/23_19:45:16 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:45:16 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[17926]: 2007/10/23_19:45:16 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[17926]: 2007/10/23_19:45:16 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
crmd[17921]: 2007/10/23_19:45:16 debug: register_fsa_input_adv: route_message appended FSA input 32 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[17926]: 2007/10/23_19:45:16 debug: native_assign_node: Assigning prec370e to prmDummyB
crmd[17921]: 2007/10/23_19:45:16 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:16 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-2.bz2
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_LOG   
tengine[17925]: 2007/10/23_19:45:16 info: unpack_graph: Unpacked transition 2: 0 actions in 0 synapses
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:16 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:45:16 debug: print_graph: ## Empty transition graph ##
pengine[17926]: 2007/10/23_19:45:16 notice: NoRoleChange: Leave resource prmDummyA	(prec370e)
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 debug: run_graph: ====================================================
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 info: run_graph: Transition 2: (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0)
pengine[17926]: 2007/10/23_19:45:16 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[17925]: 2007/10/23_19:45:16 debug: print_graph: ## Empty transition graph ##
pengine[17926]: 2007/10/23_19:45:16 notice: NoRoleChange: Leave resource prmDummyB	(prec370e)
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[17925]: 2007/10/23_19:45:16 info: notify_crmd: Transition 2 status: te_complete - <null>
crmd[17921]: 2007/10/23_19:45:16 debug: do_te_invoke: Starting a transition
tengine[17925]: 2007/10/23_19:45:16 debug: print_graph: ## Empty transition graph ##
crmd[17921]: 2007/10/23_19:45:16 debug: handle_request: Transition complete: te_complete/(null)
crmd[17921]: 2007/10/23_19:45:16 debug: register_fsa_input_adv: route_message appended FSA input 33 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[17921]: 2007/10/23_19:45:16 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[17921]: 2007/10/23_19:45:16 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[17921]: 2007/10/23_19:45:16 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
pengine[17926]: 2007/10/23_19:45:16 info: process_pe_message: Transition 2: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-2.bz2
pengine[17926]: 2007/10/23_19:45:16 info: process_pe_message: Configuration ERRORs found during PE processing.  Please run "crm_verify -L" to identify issues.
Dummy[17979][17985]: 2007/10/23_19:45:25 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:45:25 info: Managed prmDummyA:monitor process 17979 exited with return code 0.
Dummy[17986][17992]: 2007/10/23_19:45:25 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:45:25 info: Managed prmDummyB:monitor process 17986 exited with return code 0.
Dummy[17993][17999]: 2007/10/23_19:45:35 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:45:35 info: Managed prmDummyA:monitor process 17993 exited with return code 0.
Dummy[18000][18006]: 2007/10/23_19:45:35 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:45:35 info: Managed prmDummyB:monitor process 18000 exited with return code 0.
Dummy[18007][18013]: 2007/10/23_19:45:45 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:45:45 info: Managed prmDummyA:monitor process 18007 exited with return code 0.
Dummy[18014][18020]: 2007/10/23_19:45:45 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:45:45 info: Managed prmDummyB:monitor process 18014 exited with return code 0.
Dummy[18021][18027]: 2007/10/23_19:45:55 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:45:55 info: Managed prmDummyA:monitor process 18021 exited with return code 0.
Dummy[18028][18034]: 2007/10/23_19:45:55 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:45:55 info: Managed prmDummyB:monitor process 18028 exited with return code 0.
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: - <cib epoch="2" num_updates="19"/>
mgmtd[17922]: 2007/10/23_19:46:01 debug: update cib finished
crmd[17921]: 2007/10/23_19:46:01 debug: handle_request: Transition cancelled: te_abort/Non-status change
tengine[17925]: 2007/10/23_19:46:01 debug: te_update_diff: Processing diff (cib_replace): 0.2.19 -> 0.3.1
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: + <cib epoch="3" num_updates="1">
crmd[17921]: 2007/10/23_19:46:01 debug: register_fsa_input_adv: route_message appended FSA input 34 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[17925]: 2007/10/23_19:46:01 debug: need_abort: Aborting on change to epoch
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +   <configuration>
crmd[17921]: 2007/10/23_19:46:01 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs <cib epoch="3" num_updates="1">
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +     <resources>
crmd[17921]: 2007/10/23_19:46:01 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs   <configuration>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +       <group id="grpDummy">
crmd[17921]: 2007/10/23_19:46:01 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs     <resources>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +         <primitive id="prmDummyC" class="ocf" type="Dummy" provider="heartbeat">
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs       <group id="grpDummy">
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +           <operations>
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs         <primitive id="prmDummyC" class="ocf" type="Dummy" provider="heartbeat">
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +             <op id="opDummyCStart" name="start" timeout="60s" on_fail="fence"/>
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs           <operations>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +             <op id="opDummyCMonitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummyCStart" name="start" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +             <op id="opDummyCStop" name="stop" timeout="60s" on_fail="fence"/>
crmd[17921]: 2007/10/23_19:46:01 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummyCMonitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +           </operations>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummyCStop" name="stop" timeout="60s" on_fail="fence"/>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +         </primitive>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs           </operations>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +       </group>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs         </primitive>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +     </resources>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs       </group>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: +   </configuration>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs     </resources>
cib[17917]: 2007/10/23_19:46:01 info: log_data_element: cib:diff: + </cib>
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs   </configuration>
cib[17917]: 2007/10/23_19:46:01 debug: send_peer_reply: Sending update diff 0.2.19 -> 0.3.1
tengine[17925]: 2007/10/23_19:46:01 debug: log_data_element: need_abort: Abort: CIB Attrs </cib>
tengine[17925]: 2007/10/23_19:46:01 info: update_abort_priority: Abort priority upgraded to 1000000
tengine[17925]: 2007/10/23_19:46:01 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
tengine[17925]: 2007/10/23_19:46:01 debug: notify_crmd: Transition 2 status: te_abort - Non-status change
tengine[17925]: 2007/10/23_19:46:01 debug: print_graph: ## Empty transition graph ##
cib[18036]: 2007/10/23_19:46:01 debug: write_cib_contents: Archiving current version
cib[18036]: 2007/10/23_19:46:01 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
crmd[17921]: 2007/10/23_19:46:01 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1193136361-23
pengine[17926]: 2007/10/23_19:46:01 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
cib[18036]: 2007/10/23_19:46:01 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
crmd[17921]: 2007/10/23_19:46:01 debug: register_fsa_input_adv: route_message appended FSA input 35 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[17926]: 2007/10/23_19:46:01 debug: unpack_config: Default action timeout: 120s
cib[18036]: 2007/10/23_19:46:01 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
crmd[17921]: 2007/10/23_19:46:01 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[17926]: 2007/10/23_19:46:01 debug: unpack_config: Default stickiness: 1000000
cib[18036]: 2007/10/23_19:46:01 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_LOG   
pengine[17926]: 2007/10/23_19:46:01 debug: unpack_config: Default failure stickiness: -1000000
cib[18036]: 2007/10/23_19:46:01 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
crmd[17921]: 2007/10/23_19:46:01 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
pengine[17926]: 2007/10/23_19:46:01 debug: unpack_config: STONITH of failed nodes is disabled
cib[18036]: 2007/10/23_19:46:01 debug: write_cib_contents: Verified CIB archive
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[17926]: 2007/10/23_19:46:01 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
pengine[17926]: 2007/10/23_19:46:01 notice: unpack_config: On loss of CCM Quorum: Ignore
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
pengine[17926]: 2007/10/23_19:46:01 info: determine_online_status: Node prec370e is online
crmd[17921]: 2007/10/23_19:46:01 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:46:01 debug: do_te_invoke: Starting a transition
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 info: determine_online_status: Node prec370d is online
pengine[17926]: 2007/10/23_19:46:01 notice: group_print: Resource Group: grpDummy
pengine[17926]: 2007/10/23_19:46:01 notice: native_print:     prmDummyC	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:46:01 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:46:01 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[17926]: 2007/10/23_19:46:01 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[17926]: 2007/10/23_19:46:01 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[17926]: 2007/10/23_19:46:01 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
tengine[17925]: 2007/10/23_19:46:01 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-3.bz2
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 debug: native_print: Allocating: prmDummyC	(heartbeat::ocf:Dummy):	Stopped 
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyC, Node[0] prec370e: 1000000
tengine[17925]: 2007/10/23_19:46:01 info: unpack_graph: Unpacked transition 3: 13 actions in 13 synapses
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyC, Node[1] prec370d: 200
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Assigning prec370e to prmDummyC
pengine[17926]: 2007/10/23_19:46:01 debug: native_color: prmDummyA: Pre-Processing group:internal_colocation (prmDummyC)
tengine[17925]: 2007/10/23_19:46:01 debug: initiate_action: Action 5: Increasing IDLE timer to 240000
pengine[17926]: 2007/10/23_19:46:01 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
tengine[17925]: 2007/10/23_19:46:01 info: send_rsc_command: Initiating action 5: prmDummyC_monitor_0 on prec370e
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: -1000000
tengine[17925]: 2007/10/23_19:46:01 debug: send_rsc_command: Action 5: Increasing transition 3 timeout to 360000 (2*120000 + 120000)
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Assigning prec370e to prmDummyA
tengine[17925]: 2007/10/23_19:46:01 info: send_rsc_command: Initiating action 7: prmDummyC_monitor_0 on prec370d
pengine[17926]: 2007/10/23_19:46:01 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
crmd[17921]: 2007/10/23_19:46:01 debug: get_lrm_resource: Adding rsc prmDummyC before operation
tengine[17925]: 2007/10/23_19:46:01 debug: run_graph: Transition 3: (Complete=0, Pending=0, Fired=2, Skipped=0, Incomplete=11)
pengine[17926]: 2007/10/23_19:46:01 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
lrmd[17918]: 2007/10/23_19:46:01 debug: on_msg_add_rsc:client [17921] adds resource prmDummyC
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
crmd[17921]: 2007/10/23_19:46:01 info: do_lrm_rsc_op: Performing op=prmDummyC_monitor_0 key=5:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
pengine[17926]: 2007/10/23_19:46:01 debug: native_assign_node: Assigning prec370e to prmDummyB
lrmd[17918]: 2007/10/23_19:46:01 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyC
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
lrmd[17918]: 2007/10/23_19:46:01 debug: on_msg_perform_op: add an operation operation monitor[8] on ocf::Dummy::prmDummyC for client 17921, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
pengine[17926]: 2007/10/23_19:46:01 notice: StartRsc:  prec370e	Start prmDummyC
lrmd[17918]: 2007/10/23_19:46:01 info: rsc:prmDummyC: monitor
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 notice: RecurringOp: prec370e	   prmDummyC_monitor_10000
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
crmd[17921]: 2007/10/23_19:46:01 debug: do_lrm_rsc_op: Recording pending op: 8 - prmDummyC_monitor_0 prmDummyC:8
pengine[17926]: 2007/10/23_19:46:01 notice: NoRoleChange: Leave resource prmDummyA	(prec370e)
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 notice: NoRoleChange: Leave resource prmDummyB	(prec370e)
pengine[17926]: 2007/10/23_19:46:01 ERROR: unpack_operation: Specifying on_fail=fence and stonith-enabled=false makes no sense
pengine[17926]: 2007/10/23_19:46:01 debug: update_action:    * (implies right) Marking action prmDummyA_start_0 mandatory because of prmDummyC_start_0
pengine[17926]: 2007/10/23_19:46:01 debug: update_action:    * (implies right) Marking action prmDummyB_start_0 mandatory because of prmDummyA_start_0
pengine[17926]: 2007/10/23_19:46:01 debug: update_action:    * (implies right) Marking action prmDummyB_monitor_10000 mandatory because of prmDummyB_start_0
pengine[17926]: 2007/10/23_19:46:01 debug: update_action:    * (implies right) Marking action prmDummyA_monitor_10000 mandatory because of prmDummyA_start_0
cib[18036]: 2007/10/23_19:46:01 debug: write_cib_contents: Wrote CIB to disk
cib[18036]: 2007/10/23_19:46:01 info: write_cib_contents: Wrote version 0.3.1 of the CIB to disk (digest: 13448e69e76c597686786eff8c981e3b)
pengine[17926]: 2007/10/23_19:46:01 info: process_pe_message: Transition 3: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-3.bz2
pengine[17926]: 2007/10/23_19:46:01 info: process_pe_message: Configuration ERRORs found during PE processing.  Please run "crm_verify -L" to identify issues.
cib[18036]: 2007/10/23_19:46:01 debug: write_cib_contents: Wrote digest to disk
cib[18036]: 2007/10/23_19:46:01 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[18036]: 2007/10/23_19:46:01 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[18036]: 2007/10/23_19:46:01 debug: write_cib_contents: Wrote and verified CIB
Dummy[18037][18043]: 2007/10/23_19:46:01 DEBUG: prmDummyC monitor : 7
lrmd[17918]: 2007/10/23_19:46:01 WARN: Managed prmDummyC:monitor process 18037 exited with return code 7.
crmd[17921]: 2007/10/23_19:46:01 info: process_lrm_event: LRM operation prmDummyC_monitor_0 (call=8, rc=7) complete 
crmd[17921]: 2007/10/23_19:46:01 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyC_monitor_0 (0:7;5:3:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:46:01 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:46:01 debug: do_update_resource: Sent resource state update message: 41
crmd[17921]: 2007/10/23_19:46:01 debug: process_lrm_event: Op prmDummyC_monitor_0 (call=8): Confirmed
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: - <cib num_updates="1"/>
mgmtd[17922]: 2007/10/23_19:46:01 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:01 debug: te_update_diff: Processing diff (cib_update): 0.3.1 -> 0.3.2
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: + <cib num_updates="2">
tengine[17925]: 2007/10/23_19:46:01 info: match_graph_event: Action prmDummyC_monitor_0 (5) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:46:01 info: send_rsc_command: Initiating action 4: probe_complete on prec370e
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:01 debug: send_rsc_command: Skipping wait for 4
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:01 debug: run_graph: Transition 3: (Complete=1, Pending=1, Fired=1, Skipped=0, Incomplete=10)
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[17925]: 2007/10/23_19:46:01 debug: run_graph: Transition 3: (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=10)
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC" type="Dummy" class="ocf" provider="heartbeat">
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyC_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="5:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;5:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="8" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:01 debug: send_peer_reply: Sending update diff 0.3.1 -> 0.3.2
crmd[17921]: 2007/10/23_19:46:01 debug: cib_rsc_callback: Resource update 41 complete: rc=0
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: - <cib num_updates="2"/>
mgmtd[17922]: 2007/10/23_19:46:01 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:01 debug: te_update_diff: Processing diff (cib_modify): 0.3.2 -> 0.3.3
cib[17917]: 2007/10/23_19:46:01 debug: log_data_element: cib:diff: + <cib num_updates="3"/>
cib[17917]: 2007/10/23_19:46:01 debug: send_peer_reply: Sending update diff 0.3.2 -> 0.3.3
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.3 -> 0.3.4
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="3"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="4">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC" type="Dummy" class="ocf" provider="heartbeat">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyC_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="7:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:7;7:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="4" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.3 -> 0.3.4
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyC_monitor_0 (7) confirmed on prec370d (rc=0)
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 6: probe_complete on prec370d
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyC_start_0 key=9:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
tengine[17925]: 2007/10/23_19:46:03 debug: send_rsc_command: Skipping wait for 6
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=3, Pending=0, Fired=1, Skipped=0, Incomplete=9)
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyC
tengine[17925]: 2007/10/23_19:46:03 info: te_pseudo_action: Pseudo action 3 fired and confirmed
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation start[9] on ocf::Dummy::prmDummyC for client 17921, its parameters: CRM_meta_id=[opDummyCStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=4, Pending=0, Fired=1, Skipped=0, Incomplete=8)
lrmd[17918]: 2007/10/23_19:46:03 info: rsc:prmDummyC: start
tengine[17925]: 2007/10/23_19:46:03 info: te_pseudo_action: Pseudo action 15 fired and confirmed
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 9: prmDummyC_start_0 on prec370e
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=5, Pending=0, Fired=2, Skipped=0, Incomplete=6)
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=6, Pending=1, Fired=0, Skipped=0, Incomplete=6)
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 9 - prmDummyC_start_0 prmDummyC:9
Dummy[18044][18051]: 2007/10/23_19:46:03 DEBUG: prmDummyC start : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyC:start process 18044 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyC_start_0 (call=9, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyC_start_0 (0:0;9:3:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:46:03 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:46:03 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[17921]: 2007/10/23_19:46:03 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 44
crmd[17921]: 2007/10/23_19:46:03 debug: process_lrm_event: Op prmDummyC_start_0 (call=9): Confirmed
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="4"/>
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 44 complete: rc=0
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.4 -> 0.3.5
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="5">
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyC_start_0 (9) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 10: prmDummyC_monitor_10000 on prec370e
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 12: prmDummyA_start_0 on prec370e
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyC_monitor_10000 key=10:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=7, Pending=0, Fired=2, Skipped=0, Incomplete=4)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC">
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation monitor[10] on ocf::Dummy::prmDummyC for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyCMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyC_start_0" operation="start" crm-debug-origin="do_update_resource" transition_key="9:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;9:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="9" crm_feature_set="2.0" rc_code="0" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8" op_force_restart=" state " op_restart_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.4 -> 0.3.5
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 10 - prmDummyC_monitor_10000 prmDummyC:10
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyA_start_0 key=12:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation start[11] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_id=[opDummyAStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
lrmd[17918]: 2007/10/23_19:46:03 info: rsc:prmDummyA: start
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 11 - prmDummyA_start_0 prmDummyA:11
Dummy[18052][18064]: 2007/10/23_19:46:03 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyC:monitor process 18052 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyC_monitor_10000 (call=10, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 45
Dummy[18055][18065]: 2007/10/23_19:46:03 DEBUG: prmDummyA start : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyA:start process 18055 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyA_start_0 (call=11, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_start_0 (0:0;12:3:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:46:03 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:46:03 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[17921]: 2007/10/23_19:46:03 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 46
crmd[17921]: 2007/10/23_19:46:03 debug: process_lrm_event: Op prmDummyA_start_0 (call=11): Confirmed
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.5 -> 0.3.6
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="5"/>
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyC_monitor_10000 (10) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="6">
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=8, Pending=1, Fired=0, Skipped=0, Incomplete=4)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyC_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="10:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;10:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="10" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.5 -> 0.3.6
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 45 complete: rc=0
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="6">
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.6 -> 0.3.7
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   <status>
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyA_start_0 (12) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 1: prmDummyA_monitor_10000 on prec370e
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 14: prmDummyB_start_0 on prec370e
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         <lrm_resources>
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 46 complete: rc=0
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=9, Pending=0, Fired=2, Skipped=0, Incomplete=2)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyA">
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyA_monitor_10000 key=1:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -             <lrm_rsc_op transition_key="5:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;5:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="4" id="prmDummyA_start_0"/>
lrmd[17918]: 2007/10/23_19:46:03 debug: cancel_op: operation monitor[5] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyAMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  cancelled
crmd[17921]: 2007/10/23_19:46:03 debug: cancel_op: Cancelling op 5 for prmDummyA (prmDummyA:5)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         </lrm_resources>
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation monitor[12] on ocf::Dummy::prmDummyA for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyAMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - </cib>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="7">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op transition_key="12:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;12:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="11" id="prmDummyA_start_0"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.6 -> 0.3.7
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 12 - prmDummyA_monitor_10000 prmDummyA:12
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyB_start_0 key=14:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation start[13] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_id=[opDummyBStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
lrmd[17918]: 2007/10/23_19:46:03 info: rsc:prmDummyB: start
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 13 - prmDummyB_start_0 prmDummyB:13
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyA_monitor_10000 (call=5, rc=-2) Cancelled 
crmd[17921]: 2007/10/23_19:46:03 debug: delete_op_entry: async: Sending delete op for prmDummyA_monitor_10000 (call=5)
crmd[17921]: 2007/10/23_19:46:03 debug: process_lrm_event: Op prmDummyA_monitor_10000 (call=5): Confirmed
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="7">
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_delete): 0.3.7 -> 0.3.8
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyA">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -             <lrm_rsc_op id="prmDummyA_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="6:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;6:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="5" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - </cib>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="8"/>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.7 -> 0.3.8
Dummy[18066][18075]: 2007/10/23_19:46:03 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyA:monitor process 18066 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyA_monitor_10000 (call=12, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 48
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="8"/>
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.8 -> 0.3.9
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="9">
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 48 complete: rc=0
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyA_monitor_10000 (1) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=10, Pending=1, Fired=0, Skipped=0, Incomplete=2)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyA_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="1:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;1:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="12" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.8 -> 0.3.9
Dummy[18069][18079]: 2007/10/23_19:46:03 DEBUG: prmDummyB start : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyB:start process 18069 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyB_start_0 (call=13, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_start_0 (0:0;14:3:680ed76a-8688-4403-8e3d-b1f808edf33f)

crmd[17921]: 2007/10/23_19:46:03 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[17921]: 2007/10/23_19:46:03 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[17921]: 2007/10/23_19:46:03 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 49
crmd[17921]: 2007/10/23_19:46:03 debug: process_lrm_event: Op prmDummyB_start_0 (call=13): Confirmed
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="9">
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.9 -> 0.3.10
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   <status>
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyB_start_0 (14) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:03 info: te_pseudo_action: Pseudo action 16 fired and confirmed
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[17925]: 2007/10/23_19:46:03 info: send_rsc_command: Initiating action 2: prmDummyB_monitor_10000 on prec370e
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         <lrm_resources>
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=11, Pending=0, Fired=2, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyB">
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: Transition 3: (Complete=12, Pending=1, Fired=0, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -             <lrm_rsc_op transition_key="7:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;7:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="6" id="prmDummyB_start_0"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           </lrm_resource>
lrmd[17918]: 2007/10/23_19:46:03 debug: cancel_op: operation monitor[7] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyBMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  cancelled
crmd[17921]: 2007/10/23_19:46:03 info: do_lrm_rsc_op: Performing op=prmDummyB_monitor_10000 key=2:3:680ed76a-8688-4403-8e3d-b1f808edf33f)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         </lrm_resources>
lrmd[17918]: 2007/10/23_19:46:03 debug: on_msg_perform_op: add an operation operation monitor[14] on ocf::Dummy::prmDummyB for client 17921, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyBMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
crmd[17921]: 2007/10/23_19:46:03 debug: cancel_op: Cancelling op 7 for prmDummyB (prmDummyB:7)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - </cib>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="10">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op transition_key="14:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;14:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="13" id="prmDummyB_start_0"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.9 -> 0.3.10
crmd[17921]: 2007/10/23_19:46:03 debug: do_lrm_rsc_op: Recording pending op: 14 - prmDummyB_monitor_10000 prmDummyB:14
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 49 complete: rc=0
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyB_monitor_10000 (call=7, rc=-2) Cancelled 
crmd[17921]: 2007/10/23_19:46:03 debug: delete_op_entry: async: Sending delete op for prmDummyB_monitor_10000 (call=7)
crmd[17921]: 2007/10/23_19:46:03 debug: process_lrm_event: Op prmDummyB_monitor_10000 (call=7): Confirmed
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="10">
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   <status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         <lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyB">
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -             <lrm_rsc_op id="prmDummyB_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="8:1:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;8:1:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="7" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -           </lrm_resource>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -         </lrm_resources>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: -   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - </cib>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="11"/>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.10 -> 0.3.11
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_delete): 0.3.10 -> 0.3.11
Dummy[18080][18086]: 2007/10/23_19:46:03 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:03 info: Managed prmDummyB:monitor process 18080 exited with return code 0.
crmd[17921]: 2007/10/23_19:46:03 info: process_lrm_event: LRM operation prmDummyB_monitor_10000 (call=14, rc=0) complete 
crmd[17921]: 2007/10/23_19:46:03 debug: do_update_resource: Sent resource state update message: 51
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: - <cib num_updates="11"/>
tengine[17925]: 2007/10/23_19:46:03 debug: te_update_diff: Processing diff (cib_update): 0.3.11 -> 0.3.12
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + <cib num_updates="12">
mgmtd[17922]: 2007/10/23_19:46:03 debug: update cib finished
crmd[17921]: 2007/10/23_19:46:03 debug: cib_rsc_callback: Resource update 51 complete: rc=0
tengine[17925]: 2007/10/23_19:46:03 info: match_graph_event: Action prmDummyB_monitor_10000 (2) confirmed on prec370e (rc=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   <status>
crmd[17921]: 2007/10/23_19:46:03 debug: handle_request: Transition complete: te_complete/(null)
tengine[17925]: 2007/10/23_19:46:03 debug: run_graph: ====================================================
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[17921]: 2007/10/23_19:46:03 debug: register_fsa_input_adv: route_message appended FSA input 36 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
tengine[17925]: 2007/10/23_19:46:03 info: run_graph: Transition 3: (Complete=13, Pending=0, Fired=0, Skipped=0, Incomplete=0)
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[17921]: 2007/10/23_19:46:03 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[17925]: 2007/10/23_19:46:03 info: notify_crmd: Transition 3 status: te_complete - <null>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         <lrm_resources>
crmd[17921]: 2007/10/23_19:46:03 debug: do_fsa_action: actions:trace: 	// A_LOG   
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
crmd[17921]: 2007/10/23_19:46:03 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyB_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="2:3:680ed76a-8688-4403-8e3d-b1f808edf33f" transition_magic="0:0;2:3:680ed76a-8688-4403-8e3d-b1f808edf33f" call_id="14" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
crmd[17921]: 2007/10/23_19:46:03 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +           </lrm_resource>
crmd[17921]: 2007/10/23_19:46:03 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[17921]: 2007/10/23_19:46:03 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +       </lrm>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +     </node_state>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: +   </status>
cib[17917]: 2007/10/23_19:46:03 debug: log_data_element: cib:diff: + </cib>
cib[17917]: 2007/10/23_19:46:03 debug: send_peer_reply: Sending update diff 0.3.11 -> 0.3.12
cib[17917]: 2007/10/23_19:46:04 debug: log_data_element: cib:diff: - <cib num_updates="12"/>
cib[17917]: 2007/10/23_19:46:04 debug: log_data_element: cib:diff: + <cib num_updates="13"/>
mgmtd[17922]: 2007/10/23_19:46:04 debug: update cib finished
tengine[17925]: 2007/10/23_19:46:04 debug: te_update_diff: Processing diff (cib_modify): 0.3.12 -> 0.3.13
cib[17917]: 2007/10/23_19:46:04 debug: send_peer_reply: Sending update diff 0.3.12 -> 0.3.13
cib[17917]: 2007/10/23_19:46:09 info: sync_our_cib: Syncing CIB to all peers
Dummy[18088][18094]: 2007/10/23_19:46:13 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:13 info: Managed prmDummyC:monitor process 18088 exited with return code 0.
Dummy[18095][18101]: 2007/10/23_19:46:13 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:13 info: Managed prmDummyA:monitor process 18095 exited with return code 0.
Dummy[18102][18108]: 2007/10/23_19:46:13 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:13 info: Managed prmDummyB:monitor process 18102 exited with return code 0.
Dummy[18110][18116]: 2007/10/23_19:46:23 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:23 info: Managed prmDummyC:monitor process 18110 exited with return code 0.
Dummy[18117][18123]: 2007/10/23_19:46:23 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:23 info: Managed prmDummyA:monitor process 18117 exited with return code 0.
Dummy[18124][18130]: 2007/10/23_19:46:23 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:23 info: Managed prmDummyB:monitor process 18124 exited with return code 0.
Dummy[18131][18137]: 2007/10/23_19:46:33 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:33 info: Managed prmDummyC:monitor process 18131 exited with return code 0.
Dummy[18138][18144]: 2007/10/23_19:46:33 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:33 info: Managed prmDummyA:monitor process 18138 exited with return code 0.
Dummy[18145][18151]: 2007/10/23_19:46:33 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:33 info: Managed prmDummyB:monitor process 18145 exited with return code 0.
Dummy[18152][18158]: 2007/10/23_19:46:43 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:43 info: Managed prmDummyC:monitor process 18152 exited with return code 0.
Dummy[18159][18165]: 2007/10/23_19:46:43 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:43 info: Managed prmDummyA:monitor process 18159 exited with return code 0.
Dummy[18166][18172]: 2007/10/23_19:46:43 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:43 info: Managed prmDummyB:monitor process 18166 exited with return code 0.
Dummy[18175][18181]: 2007/10/23_19:46:53 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:46:53 info: Managed prmDummyC:monitor process 18175 exited with return code 0.
Dummy[18184][18190]: 2007/10/23_19:46:53 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:46:53 info: Managed prmDummyA:monitor process 18184 exited with return code 0.
Dummy[18191][18197]: 2007/10/23_19:46:53 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:46:53 info: Managed prmDummyB:monitor process 18191 exited with return code 0.
Dummy[18198][18204]: 2007/10/23_19:47:03 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:03 info: Managed prmDummyC:monitor process 18198 exited with return code 0.
Dummy[18205][18211]: 2007/10/23_19:47:03 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:03 info: Managed prmDummyA:monitor process 18205 exited with return code 0.
Dummy[18212][18218]: 2007/10/23_19:47:03 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:03 info: Managed prmDummyB:monitor process 18212 exited with return code 0.
Dummy[18219][18225]: 2007/10/23_19:47:13 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:13 info: Managed prmDummyC:monitor process 18219 exited with return code 0.
Dummy[18226][18232]: 2007/10/23_19:47:13 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:13 info: Managed prmDummyA:monitor process 18226 exited with return code 0.
Dummy[18233][18239]: 2007/10/23_19:47:13 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:13 info: Managed prmDummyB:monitor process 18233 exited with return code 0.
Dummy[18240][18246]: 2007/10/23_19:47:23 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:23 info: Managed prmDummyC:monitor process 18240 exited with return code 0.
Dummy[18247][18253]: 2007/10/23_19:47:23 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:23 info: Managed prmDummyA:monitor process 18247 exited with return code 0.
Dummy[18254][18260]: 2007/10/23_19:47:23 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:23 info: Managed prmDummyB:monitor process 18254 exited with return code 0.
Dummy[18261][18267]: 2007/10/23_19:47:33 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:33 info: Managed prmDummyC:monitor process 18261 exited with return code 0.
Dummy[18268][18274]: 2007/10/23_19:47:33 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:33 info: Managed prmDummyA:monitor process 18268 exited with return code 0.
Dummy[18275][18281]: 2007/10/23_19:47:33 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:33 info: Managed prmDummyB:monitor process 18275 exited with return code 0.
Dummy[18282][18288]: 2007/10/23_19:47:43 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:43 info: Managed prmDummyC:monitor process 18282 exited with return code 0.
Dummy[18289][18295]: 2007/10/23_19:47:43 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:43 info: Managed prmDummyA:monitor process 18289 exited with return code 0.
Dummy[18296][18302]: 2007/10/23_19:47:43 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:43 info: Managed prmDummyB:monitor process 18296 exited with return code 0.
Dummy[18303][18309]: 2007/10/23_19:47:53 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:47:53 info: Managed prmDummyC:monitor process 18303 exited with return code 0.
Dummy[18310][18316]: 2007/10/23_19:47:53 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:47:53 info: Managed prmDummyA:monitor process 18310 exited with return code 0.
Dummy[18317][18323]: 2007/10/23_19:47:53 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:47:53 info: Managed prmDummyB:monitor process 18317 exited with return code 0.
Dummy[18326][18332]: 2007/10/23_19:48:03 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:03 info: Managed prmDummyC:monitor process 18326 exited with return code 0.
Dummy[18333][18339]: 2007/10/23_19:48:03 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:03 info: Managed prmDummyA:monitor process 18333 exited with return code 0.
Dummy[18340][18346]: 2007/10/23_19:48:03 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:03 info: Managed prmDummyB:monitor process 18340 exited with return code 0.
Dummy[18349][18355]: 2007/10/23_19:48:13 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:13 info: Managed prmDummyC:monitor process 18349 exited with return code 0.
Dummy[18356][18362]: 2007/10/23_19:48:13 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:13 info: Managed prmDummyA:monitor process 18356 exited with return code 0.
Dummy[18363][18369]: 2007/10/23_19:48:13 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:13 info: Managed prmDummyB:monitor process 18363 exited with return code 0.
Dummy[18372][18378]: 2007/10/23_19:48:23 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:23 info: Managed prmDummyC:monitor process 18372 exited with return code 0.
Dummy[18379][18385]: 2007/10/23_19:48:23 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:23 info: Managed prmDummyA:monitor process 18379 exited with return code 0.
Dummy[18386][18392]: 2007/10/23_19:48:23 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:23 info: Managed prmDummyB:monitor process 18386 exited with return code 0.
Dummy[18393][18399]: 2007/10/23_19:48:33 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:33 info: Managed prmDummyC:monitor process 18393 exited with return code 0.
Dummy[18400][18406]: 2007/10/23_19:48:33 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:33 info: Managed prmDummyA:monitor process 18400 exited with return code 0.
Dummy[18407][18413]: 2007/10/23_19:48:33 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:33 info: Managed prmDummyB:monitor process 18407 exited with return code 0.
Dummy[18414][18420]: 2007/10/23_19:48:43 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:43 info: Managed prmDummyC:monitor process 18414 exited with return code 0.
Dummy[18421][18427]: 2007/10/23_19:48:43 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:43 info: Managed prmDummyA:monitor process 18421 exited with return code 0.
Dummy[18428][18434]: 2007/10/23_19:48:43 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:43 info: Managed prmDummyB:monitor process 18428 exited with return code 0.
Dummy[18436][18442]: 2007/10/23_19:48:53 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:48:53 info: Managed prmDummyC:monitor process 18436 exited with return code 0.
Dummy[18443][18449]: 2007/10/23_19:48:53 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:48:53 info: Managed prmDummyA:monitor process 18443 exited with return code 0.
Dummy[18450][18456]: 2007/10/23_19:48:53 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:48:53 info: Managed prmDummyB:monitor process 18450 exited with return code 0.
Dummy[18457][18463]: 2007/10/23_19:49:03 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:49:03 info: Managed prmDummyC:monitor process 18457 exited with return code 0.
Dummy[18464][18470]: 2007/10/23_19:49:03 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:49:03 info: Managed prmDummyA:monitor process 18464 exited with return code 0.
Dummy[18471][18477]: 2007/10/23_19:49:03 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:49:03 info: Managed prmDummyB:monitor process 18471 exited with return code 0.
Dummy[18478][18484]: 2007/10/23_19:49:13 DEBUG: prmDummyC monitor : 0
lrmd[17918]: 2007/10/23_19:49:13 info: Managed prmDummyC:monitor process 18478 exited with return code 0.
Dummy[18485][18491]: 2007/10/23_19:49:13 DEBUG: prmDummyA monitor : 0
lrmd[17918]: 2007/10/23_19:49:13 info: Managed prmDummyA:monitor process 18485 exited with return code 0.
Dummy[18492][18498]: 2007/10/23_19:49:13 DEBUG: prmDummyB monitor : 0
lrmd[17918]: 2007/10/23_19:49:13 info: Managed prmDummyB:monitor process 18492 exited with return code 0.
