logd[32260]: 2007/10/19_11:27:07 info: logd started with /etc/logd.cf.
logd[32261]: 2007/10/19_11:27:07 info: G_main_add_SignalHandler: Added signal handler for signal 15
logd[32260]: 2007/10/19_11:27:07 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32281]: 2007/10/19_11:27:07 info: Enabling logging daemon 
heartbeat[32281]: 2007/10/19_11:27:07 info: logfile and debug file are those specified in logd config file (default /etc/logd.cf)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(keepalive,2)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(deadtime,30)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(initdead,30)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(warntime,20)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(udpport,694)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(bcast,eth2)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(node,prec370d)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(node,prec370e)
heartbeat[32281]: 2007/10/19_11:27:07 debug: uid=hacluster, gid=<null>
heartbeat[32281]: 2007/10/19_11:27:07 debug: uid=hacluster, gid=<null>
heartbeat[32281]: 2007/10/19_11:27:07 debug: uid=<null>, gid=haclient
heartbeat[32281]: 2007/10/19_11:27:07 debug: uid=root, gid=<null>
heartbeat[32281]: 2007/10/19_11:27:07 debug: uid=<null>, gid=haclient
heartbeat[32281]: 2007/10/19_11:27:07 debug: Beginning authentication parsing
heartbeat[32281]: 2007/10/19_11:27:07 debug: 16 max authentication methods
heartbeat[32281]: 2007/10/19_11:27:07 debug: Keyfile opened
heartbeat[32281]: 2007/10/19_11:27:07 debug: Keyfile perms OK
heartbeat[32281]: 2007/10/19_11:27:07 debug: 16 max authentication methods
heartbeat[32281]: 2007/10/19_11:27:07 debug: Found authentication method [sha1]
heartbeat[32281]: 2007/10/19_11:27:07 info: AUTH: i=1: key = 0x5d92f8, auth=0x2a96103900, authname=sha1
heartbeat[32281]: 2007/10/19_11:27:07 debug: Outbound signing method is 1
heartbeat[32281]: 2007/10/19_11:27:07 debug: Authentication parsing complete [1]
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(cluster,linux-ha)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(hopfudge,1)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(baud,19200)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(auto_failback,legacy)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(hbgenmethod,file)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(realtime,true)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(msgfmt,classic)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(conn_logd_time,60)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(log_badpack,true)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(syslogmsgfmt,false)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(coredumps,true)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(autojoin,none)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(uuidfrom,file)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(compression,zlib)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(compression_threshold,2)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(traditional_compression,no)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(max_rexmit_delay,250)
heartbeat[32281]: 2007/10/19_11:27:07 debug: Setting max_rexmit_delay to 250 ms
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(record_config_changes,on)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(record_pengine_inputs,on)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(enable_config_writes,on)
heartbeat[32281]: 2007/10/19_11:27:07 debug: add_option(memreserve,6500)
heartbeat[32281]: 2007/10/19_11:27:07 info: **************************
heartbeat[32281]: 2007/10/19_11:27:07 info: Configuration validated. Starting heartbeat 2.1.3
heartbeat[32281]: 2007/10/19_11:27:07 debug: HA configuration OK.  Heartbeat starting.
heartbeat[32282]: 2007/10/19_11:27:07 info: heartbeat: version 2.1.3
heartbeat[32282]: 2007/10/19_11:27:08 info: Heartbeat generation: 864
heartbeat[32282]: 2007/10/19_11:27:08 debug: uuid is:9d9ca527-cea9-470c-9e03-e49fe5630bba
heartbeat[32282]: 2007/10/19_11:27:08 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[32282]: 2007/10/19_11:27:08 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[32282]: 2007/10/19_11:27:08 info: Removing /var/run/heartbeat/rsctmp failed, recreating.
heartbeat[32282]: 2007/10/19_11:27:08 debug: opening bcast eth2 (UDP/IP broadcast)
heartbeat[32282]: 2007/10/19_11:27:08 debug: FIFO process pid: 32285
heartbeat[32282]: 2007/10/19_11:27:08 debug: glib: SO_BINDTODEVICE(r) set for device eth2
heartbeat[32282]: 2007/10/19_11:27:08 info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth2
heartbeat[32282]: 2007/10/19_11:27:08 debug: write process pid: 32286
heartbeat[32282]: 2007/10/19_11:27:08 debug: read child process pid: 32287
heartbeat[32282]: 2007/10/19_11:27:08 info: glib: UDP Broadcast heartbeat closed on port 694 interface eth2 - Status: 1
heartbeat[32282]: 2007/10/19_11:27:08 info: G_main_add_SignalHandler: Added signal handler for signal 17
heartbeat[32282]: 2007/10/19_11:27:08 debug: Limiting CPU: 42 CPU seconds every 60000 milliseconds
heartbeat[32282]: 2007/10/19_11:27:08 debug: pid 32282 locked in memory.
heartbeat[32282]: 2007/10/19_11:27:08 debug: Waiting for child processes to start
heartbeat[32282]: 2007/10/19_11:27:08 info: Local status now set to: 'up'
heartbeat[32282]: 2007/10/19_11:27:08 debug: All your child process are belong to us
heartbeat[32282]: 2007/10/19_11:27:08 debug: Starting local status message @ 2000 ms intervals
heartbeat[32287]: 2007/10/19_11:27:09 debug: pid 32287 locked in memory.
heartbeat[32286]: 2007/10/19_11:27:09 debug: pid 32286 locked in memory.
heartbeat[32287]: 2007/10/19_11:27:09 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[32286]: 2007/10/19_11:27:09 debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
heartbeat[32285]: 2007/10/19_11:27:09 debug: pid 32285 locked in memory.
heartbeat[32285]: 2007/10/19_11:27:09 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[32282]: 2007/10/19_11:27:09 info: Link prec370d:eth2 up.
heartbeat[32282]: 2007/10/19_11:27:09 debug: sending reqnodes msg to node prec370d
heartbeat[32282]: 2007/10/19_11:27:09 info: Status update for node prec370d: status up
heartbeat[32282]: 2007/10/19_11:27:09 debug: Status seqno: 2 msgtime: 1192760827
heartbeat[32282]: 2007/10/19_11:27:09 info: Link prec370e:eth2 up.
heartbeat[32282]: 2007/10/19_11:27:09 debug: Get a reqnodes message from prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: get_delnodelist: delnodelist= 
heartbeat[32282]: 2007/10/19_11:27:09 debug: Get a repnodes msg from prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: nodelist received:prec370d prec370e 
heartbeat[32282]: 2007/10/19_11:27:09 info: Comm_now_up(): updating status to active
heartbeat[32282]: 2007/10/19_11:27:09 info: Local status now set to: 'active'
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/ccm" (90,90)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/cib" (90,90)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/lrmd -r" (0,0)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/stonithd" (0,0)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/attrd" (90,90)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/crmd" (90,90)
heartbeat[32282]: 2007/10/19_11:27:09 info: Starting child client "/usr/lib64/heartbeat/mgmtd -v" (0,0)
heartbeat[32290]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/ccm" as uid 90  gid 90 (pid 32290)
heartbeat[32291]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/cib" as uid 90  gid 90 (pid 32291)
heartbeat[32292]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/lrmd -r" as uid 0  gid 0 (pid 32292)
heartbeat[32293]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/stonithd" as uid 0  gid 0 (pid 32293)
heartbeat[32294]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/attrd" as uid 90  gid 90 (pid 32294)
heartbeat[32295]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/crmd" as uid 90  gid 90 (pid 32295)
heartbeat[32296]: 2007/10/19_11:27:09 info: Starting "/usr/lib64/heartbeat/mgmtd -v" as uid 0  gid 0 (pid 32296)
lrmd[32292]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
lrmd[32292]: 2007/10/19_11:27:09 debug: LRM debug level set to 1
ccm[32290]: 2007/10/19_11:27:09 debug: Signing in with Heartbeat
lrmd[32292]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 17
lrmd[32292]: 2007/10/19_11:27:09 debug: Enabling coredumps
lrmd[32292]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 10
lrmd[32292]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 12
lrmd[32292]: 2007/10/19_11:27:09 debug: main: run the loop...
lrmd[32292]: 2007/10/19_11:27:09 info: Started.
heartbeat[32282]: 2007/10/19_11:27:09 debug: APIregistration_dispatch() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: process_registerevent() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: client->gsource = 0x5eaa08
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*process_registerevent*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*APIregistration_dispatch*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: Checking client authorization for client ccm (90:90)
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: Signing on API client 32290 (ccm)
stonithd[32293]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 10
stonithd[32293]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 12
crmd[32295]: 2007/10/19_11:27:09 info: main: CRM Hg Version: 2cff5374f61b tip

crmd[32295]: 2007/10/19_11:27:09 info: crmd_init: Starting crmd
crmd[32295]: 2007/10/19_11:27:09 debug: register_fsa_input_adv: crmd_init appended FSA input 1 (I_STARTUP) (cause=C_STARTUP) without data
crmd[32295]: 2007/10/19_11:27:09 debug: s_crmd_fsa: Processing I_STARTUP: [ state=S_STARTING cause=C_STARTUP origin=crmd_init ]
crmd[32295]: 2007/10/19_11:27:09 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:09 debug: do_fsa_action: actions:trace: 	// A_STARTUP
crmd[32295]: 2007/10/19_11:27:09 debug: do_startup: Registering Signal Handlers
crmd[32295]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
crmd[32295]: 2007/10/19_11:27:09 info: G_main_add_TriggerHandler: Added signal manual handler
crmd[32295]: 2007/10/19_11:27:09 debug: do_startup: Creating CIB and LRM objects
crmd[32295]: 2007/10/19_11:27:09 debug: do_startup: Init server comms
crmd[32295]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 17
crmd[32295]: 2007/10/19_11:27:09 debug: do_fsa_action: actions:trace: 	// A_CIB_START
crmd[32295]: 2007/10/19_11:27:09 debug: init_client_ipc_comms_nodispatch: Could not init comms on: /var/run/heartbeat/crm/cib_rw
crmd[32295]: 2007/10/19_11:27:09 debug: cib_native_signon: Connection to command channel failed
crmd[32295]: 2007/10/19_11:27:09 debug: cib_native_signon: Connection to CIB failed: connection failed
crmd[32295]: 2007/10/19_11:27:09 debug: cib_native_signoff: Signing out of the CIB Service
cib[32291]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
cib[32291]: 2007/10/19_11:27:09 info: G_main_add_TriggerHandler: Added signal manual handler
cib[32291]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 17
cib[32291]: 2007/10/19_11:27:09 info: main: Retrieval of a per-action CIB: disabled
cib[32291]: 2007/10/19_11:27:09 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32291]: 2007/10/19_11:27:09 WARN: validate_cib_digest: No on-disk digest present
cib[32291]: 2007/10/19_11:27:09 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[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]   <configuration>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     <crm_config>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       <cluster_property_set id="idCluseterPropertySet">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <attributes>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="symmetric-cluster" name="symmetric-cluster" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="no-quorum-policy" name="no-quorum-policy" value="ignore"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stonith-enabled" name="stonith-enabled" value="false"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="short-resource-names" name="short_resource_names" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="is-managed-default" name="is-managed-default" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-resource-stickiness" name="default-resource-stickiness" value="INFINITY"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stop-orphan-resources" name="stop-orphan-resources" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stop-orphan-actions" name="stop-orphan-actions" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="remove-after-stop" name="remove-after-stop" value="false"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-resource-failure-stickiness" name="default-resource-failure-stickiness" value="-INFINITY"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="stonith-action" name="stonith-action" value="reboot"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="default-action-timeout" name="default-action-timeout" value="120s"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="dc_deadtime" name="dc_deadtime" value="10s"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="cluster_recheck_interval" name="cluster_recheck_interval" value="0"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="election_timeout" name="election_timeout" value="2min"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="shutdown_escalation" name="shutdown_escalation" value="20min"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="crmd-integration-timeout" name="crmd-integration-timeout" value="3min"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="crmd-finalization-timeout" name="crmd-finalization-timeout" value="10min"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="cluster-delay" name="cluster-delay" value="120s"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-error-series-max" name="pe-error-series-max" value="-1"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-warn-series-max" name="pe-warn-series-max" value="-1"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="pe-input-series-max" name="pe-input-series-max" value="-1"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <nvpair id="startup-fencing" name="startup-fencing" value="true"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </attributes>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       </cluster_property_set>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     </crm_config>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     <nodes/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     <resources>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       <group id="grpDummy">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <primitive id="prmDummyA" class="ocf" type="Dummy" provider="heartbeat">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <operations>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAStart" name="start" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAMonitor" name="monitor" interval="10s" timeout="10s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyAStop" name="stop" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           </operations>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </primitive>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <primitive id="prmDummyB" class="ocf" type="Dummy" provider="heartbeat">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <operations>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBStart" name="start" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBMonitor" name="monitor" interval="10s" timeout="10s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]             <op id="opDummyBStop" name="stop" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           </operations>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </primitive>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       </group>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     </resources>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     <constraints>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       <rsc_location id="rlcDummy" rsc="grpDummy">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <rule score="200" id="rulNode1">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <expression value="prec370d" attribute="#uname" operation="eq" id="expNode1"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <rule score="300" id="rulNode2">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <expression value="prec370e" attribute="#uname" operation="eq" id="expNode2"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       </rsc_location>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       <rsc_location id="ping:disconn" rsc="grpDummy">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         <rule id="ping1:disconn:rule" score="-INFINITY" boolean_op="and">
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <expression id="ping1:disconn:expr:defined" attribute="default_ping_set" operation="defined"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]           <expression id="ping1:disconn:expr:positive" attribute="default_ping_set" operation="lt" value="100"/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]         </rule>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]       </rsc_location>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]     </constraints>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]   </configuration>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk]   <status/>
cib[32291]: 2007/10/19_11:27:09 info: log_data_element: readCibXmlFile: [on-disk] </cib>
cib[32291]: 2007/10/19_11:27:09 notice: readCibXmlFile: Enabling DTD validation on the existing (sane) configuration
cib[32291]: 2007/10/19_11:27:09 info: startCib: CIB Initialization completed successfully
heartbeat[32282]: 2007/10/19_11:27:09 debug: APIregistration_dispatch() {
cib[32291]: 2007/10/19_11:27:09 info: cib_register_ha: Signing in with Heartbeat
heartbeat[32282]: 2007/10/19_11:27:09 debug: process_registerevent() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: client->gsource = 0x5efea8
cib[32291]: 2007/10/19_11:27:09 info: cib_register_ha: FSA Hostname: prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*process_registerevent*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*APIregistration_dispatch*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: Checking client authorization for client cib (90:90)
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370d
cib[32291]: 2007/10/19_11:27:09 info: ccm_connect: Registering with CCM...
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370e
cib[32291]: 2007/10/19_11:27:09 WARN: ccm_connect: CCM Activation failed
heartbeat[32282]: 2007/10/19_11:27:09 debug: Signing on API client 32291 (cib)
cib[32291]: 2007/10/19_11:27:09 WARN: ccm_connect: CCM Connection failed 1 times (30 max)
ccm[32290]: 2007/10/19_11:27:09 info: Hostname: prec370e
stonithd[32293]: 2007/10/19_11:27:09 debug: pid 32293 locked in memory.
heartbeat[32282]: 2007/10/19_11:27:09 debug: APIregistration_dispatch() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: process_registerevent() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: client->gsource = 0x5f0238
stonithd[32293]: 2007/10/19_11:27:09 info: Signing in with heartbeat.
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*process_registerevent*/;
stonithd[32293]: 2007/10/19_11:27:09 debug: Setting message filter mode
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*APIregistration_dispatch*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: Checking client authorization for client stonithd (0:0)
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: Signing on API client 32293 (stonithd)
mgmtd[32296]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
mgmtd[32296]: 2007/10/19_11:27:09 debug: Enabling coredumps
mgmtd[32296]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 10
mgmtd[32296]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 12
heartbeat[32282]: 2007/10/19_11:27:09 debug: APIregistration_dispatch() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: process_registerevent() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: client->gsource = 0x5f12d8
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*process_registerevent*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*APIregistration_dispatch*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: Checking client authorization for client mgmtd (0:0)
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: Signing on API client 32296 (mgmtd)
lrmd[32292]: 2007/10/19_11:27:09 debug: on_msg_register:client mgmtd [32296] registered
stonithd[32293]: 2007/10/19_11:27:09 debug: apichan=0x519238
mgmtd[32296]: 2007/10/19_11:27:09 info: init_crm
stonithd[32293]: 2007/10/19_11:27:09 debug: callback_chan=0x5197d8
stonithd[32293]: 2007/10/19_11:27:09 notice: /usr/lib64/heartbeat/stonithd start up successfully.
stonithd[32293]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 17
attrd[32294]: 2007/10/19_11:27:09 info: G_main_add_SignalHandler: Added signal handler for signal 15
attrd[32294]: 2007/10/19_11:27:09 debug: register_with_ha: Signing in with Heartbeat
heartbeat[32282]: 2007/10/19_11:27:09 debug: APIregistration_dispatch() {
heartbeat[32282]: 2007/10/19_11:27:09 debug: process_registerevent() {
attrd[32294]: 2007/10/19_11:27:09 info: register_with_ha: Hostname: prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: client->gsource = 0x5f47c8
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*process_registerevent*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: }/*APIregistration_dispatch*/;
heartbeat[32282]: 2007/10/19_11:27:09 debug: Checking client authorization for client attrd (90:90)
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[32282]: 2007/10/19_11:27:09 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[32282]: 2007/10/19_11:27:09 debug: Signing on API client 32294 (attrd)
heartbeat[32282]: 2007/10/19_11:27:10 info: Status update for node prec370d: status active
heartbeat[32282]: 2007/10/19_11:27:10 debug: Status seqno: 7 msgtime: 1192760829
attrd[32294]: 2007/10/19_11:27:10 info: register_with_ha: UUID: 9d9ca527-cea9-470c-9e03-e49fe5630bba
attrd[32294]: 2007/10/19_11:27:10 debug: main: CIB signon attempt 0
cib[32291]: 2007/10/19_11:27:10 info: ccm_connect: Registering with CCM...
cib[32291]: 2007/10/19_11:27:10 WARN: ccm_connect: CCM Activation failed
cib[32291]: 2007/10/19_11:27:10 WARN: ccm_connect: CCM Connection failed 2 times (30 max)
cib[32291]: 2007/10/19_11:27:11 info: ccm_connect: Registering with CCM...
cib[32291]: 2007/10/19_11:27:11 WARN: ccm_connect: CCM Activation failed
cib[32291]: 2007/10/19_11:27:11 WARN: ccm_connect: CCM Connection failed 3 times (30 max)
cib[32291]: 2007/10/19_11:27:12 info: ccm_connect: Registering with CCM...
cib[32291]: 2007/10/19_11:27:12 WARN: ccm_connect: CCM Activation failed
cib[32291]: 2007/10/19_11:27:12 WARN: ccm_connect: CCM Connection failed 4 times (30 max)
ccm[32290]: 2007/10/19_11:27:13 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[32290]: 2007/10/19_11:27:13 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[32290]: 2007/10/19_11:27:13 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32282]: 2007/10/19_11:27:13 WARN: 1 lost packet(s) for [prec370d] [14:16]
heartbeat[32282]: 2007/10/19_11:27:13 info: No pkts missing from prec370d!
cib[32291]: 2007/10/19_11:27:13 info: ccm_connect: Registering with CCM...
cib[32291]: 2007/10/19_11:27:13 debug: ccm_connect: CCM Activation passed... all set to go!
cib[32291]: 2007/10/19_11:27:14 debug: Delaying cstatus request for 96 ms
ccm[32290]: 2007/10/19_11:27:14 debug: recv msg hbapi-clstat from prec370e, status:join
cib[32291]: 2007/10/19_11:27:14 info: cib_init: Starting cib mainloop
cib[32297]: 2007/10/19_11:27:14 debug: write_cib_contents: Archiving current version
cib[32297]: 2007/10/19_11:27:14 WARN: validate_cib_digest: No on-disk digest present
cib[32297]: 2007/10/19_11:27:14 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32297]: 2007/10/19_11:27:14 WARN: validate_cib_digest: No on-disk digest present
cib[32297]: 2007/10/19_11:27:14 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[32297]: 2007/10/19_11:27:14 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32297]: 2007/10/19_11:27:14 WARN: validate_cib_digest: No on-disk digest present
cib[32297]: 2007/10/19_11:27:14 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32297]: 2007/10/19_11:27:14 WARN: validate_cib_digest: No on-disk digest present
cib[32297]: 2007/10/19_11:27:14 debug: write_cib_contents: Verified CIB archive
heartbeat[32282]: 2007/10/19_11:27:14 debug: APIregistration_dispatch() {
crmd[32295]: 2007/10/19_11:27:14 debug: cib_native_signon: Connection to CIB successful
cib[32291]: 2007/10/19_11:27:14 info: cib_null_callback: Setting cib_diff_notify callbacks for mgmtd: on
attrd[32294]: 2007/10/19_11:27:14 debug: cib_native_signon: Connection to CIB successful
heartbeat[32282]: 2007/10/19_11:27:14 debug: process_registerevent() {
crmd[32295]: 2007/10/19_11:27:14 info: do_cib_control: CIB connection established
heartbeat[32282]: 2007/10/19_11:27:14 debug: client->gsource = 0x5fa998
crmd[32295]: 2007/10/19_11:27:14 debug: do_fsa_action: actions:trace: 	// A_HA_CONNECT
heartbeat[32282]: 2007/10/19_11:27:14 debug: }/*process_registerevent*/;
crmd[32295]: 2007/10/19_11:27:14 debug: register_with_ha: Signing in with Heartbeat
heartbeat[32282]: 2007/10/19_11:27:14 debug: }/*APIregistration_dispatch*/;
crmd[32295]: 2007/10/19_11:27:14 info: register_with_ha: Hostname: prec370e
heartbeat[32282]: 2007/10/19_11:27:14 debug: Checking client authorization for client crmd (90:90)
heartbeat[32282]: 2007/10/19_11:27:14 debug: create_seq_snapshot_table:no missing packets found for node prec370d
heartbeat[32282]: 2007/10/19_11:27:14 debug: create_seq_snapshot_table:no missing packets found for node prec370e
heartbeat[32282]: 2007/10/19_11:27:14 debug: Signing on API client 32295 (crmd)
cib[32291]: 2007/10/19_11:27:14 info: cib_client_status_callback: Status update: Client prec370e/cib now has status [join]
cib[32291]: 2007/10/19_11:27:14 debug: set_connected_peers: We now have 1 active peers
cib[32291]: 2007/10/19_11:27:14 info: cib_null_callback: Setting cib_refresh_notify callbacks for crmd: on
cib[32291]: 2007/10/19_11:27:14 info: cib_client_status_callback: Status update: Client prec370d/cib now has status [join]
cib[32291]: 2007/10/19_11:27:14 debug: set_connected_peers: We now have 2 active peers
cib[32291]: 2007/10/19_11:27:14 info: cib_client_status_callback: Status update: Client prec370e/cib now has status [online]
cib[32297]: 2007/10/19_11:27:14 debug: write_cib_contents: Wrote CIB to disk
cib[32297]: 2007/10/19_11:27:14 info: write_cib_contents: Wrote version 0.1.1 of the CIB to disk (digest: 50c1f1fe107ee12e01786463953a0e5a)
cib[32297]: 2007/10/19_11:27:14 debug: write_cib_contents: Wrote digest to disk
cib[32297]: 2007/10/19_11:27:14 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32297]: 2007/10/19_11:27:14 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32297]: 2007/10/19_11:27:14 WARN: validate_cib_digest: No on-disk digest present
cib[32297]: 2007/10/19_11:27:14 debug: write_cib_contents: Wrote and verified CIB
heartbeat[32282]: 2007/10/19_11:27:14 WARN: 1 lost packet(s) for [prec370d] [19:21]
heartbeat[32282]: 2007/10/19_11:27:14 info: No pkts missing from prec370d!
crmd[32295]: 2007/10/19_11:27:14 info: register_with_ha: UUID: 9d9ca527-cea9-470c-9e03-e49fe5630bba
cib[32291]: 2007/10/19_11:27:14 info: cib_client_status_callback: Status update: Client prec370d/cib now has status [online]
mgmtd[32296]: 2007/10/19_11:27:14 debug: main: run the loop...
mgmtd[32296]: 2007/10/19_11:27:14 info: Started.
crmd[32295]: 2007/10/19_11:27:15 debug: Delaying cstatus request for 137 ms
ccm[32290]: 2007/10/19_11:27:15 debug: recv msg status from prec370d, status:active
ccm[32290]: 2007/10/19_11:27:15 debug: status of node prec370d: active -> active
ccm[32290]: 2007/10/19_11:27:15 debug: recv msg hbapi-clstat from prec370d, status:join
ccm[32290]: 2007/10/19_11:27:15 debug: recv msg CCM_TYPE_PROTOVERSION from prec370d, status:[null ptr]
ccm[32290]: 2007/10/19_11:27:15 debug: send msg CCM_TYPE_PROTOVERSION to cluster, status:[null]
ccm[32290]: 2007/10/19_11:27:15 debug: node state CCM_STATE_NONE -> CCM_STATE_VERSION_REQUEST
crmd[32295]: 2007/10/19_11:27:15 info: populate_cib_nodes: Requesting the list of configured nodes
ccm[32290]: 2007/10/19_11:27:15 debug: recv msg CCM_TYPE_PROTOVERSION from prec370e, status:[null ptr]
ccm[32290]: 2007/10/19_11:27:15 debug: No quorum selected,using default quorum plugin(majority:twonodes)
ccm[32290]: 2007/10/19_11:27:15 debug: quorum plugin: majority
ccm[32290]: 2007/10/19_11:27:15 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
ccm[32290]: 2007/10/19_11:27:15 debug: total_node_count=2, total_quorum_votes=200
ccm[32290]: 2007/10/19_11:27:15 debug: quorum plugin: twonodes
ccm[32290]: 2007/10/19_11:27:15 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
cib[32291]: 2007/10/19_11:27:15 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[32290]: 2007/10/19_11:27:15 debug: total_node_count=2, total_quorum_votes=200
cib[32291]: 2007/10/19_11:27:15 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
ccm[32290]: 2007/10/19_11:27:15 info: Break tie for 2 nodes cluster
cib[32291]: 2007/10/19_11:27:15 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=1)
ccm[32290]: 2007/10/19_11:27:15 debug: node state CCM_STATE_VERSION_REQUEST -> CCM_STATE_JOINED
cib[32291]: 2007/10/19_11:27:15 debug: set_transition: CCM transition: old=(null), new=1
ccm[32290]: 2007/10/19_11:27:15 debug: dump current membership 0x2a959cf028
cib[32291]: 2007/10/19_11:27:15 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
ccm[32290]: 2007/10/19_11:27:15 debug: 	leader=prec370e
cib[32291]: 2007/10/19_11:27:15 info: cib_ccm_msg_callback: PEER: prec370e
ccm[32290]: 2007/10/19_11:27:15 debug: 	transition=1
ccm[32290]: 2007/10/19_11:27:15 debug: 	status=CCM_STATE_JOINED
ccm[32290]: 2007/10/19_11:27:15 debug: 	has_quorum=1
ccm[32290]: 2007/10/19_11:27:15 debug: 	nodename=prec370e bornon=1
ccm[32290]: 2007/10/19_11:27:15 debug: quorum is 1
ccm[32290]: 2007/10/19_11:27:15 debug: delivering new membership to 1 clients: 
ccm[32290]: 2007/10/19_11:27:15 debug: client: pid =32291
ccm[32290]: 2007/10/19_11:27:15 debug: send msg CCM_TYPE_PROTOVERSION_RESP to prec370d, status:[null]
crmd[32295]: 2007/10/19_11:27:16 notice: populate_cib_nodes: Node: prec370e (uuid: 9d9ca527-cea9-470c-9e03-e49fe5630bba)
ccm[32290]: 2007/10/19_11:27:16 WARN: ccm_state_joined: received message with unknown cookie, just dropping
ccm[32290]: 2007/10/19_11:27:16 debug: dump current membership 0x2a959cf028
ccm[32290]: 2007/10/19_11:27:16 debug: 	leader=prec370e
ccm[32290]: 2007/10/19_11:27:16 debug: 	transition=1
ccm[32290]: 2007/10/19_11:27:16 debug: 	status=CCM_STATE_JOINED
ccm[32290]: 2007/10/19_11:27:16 debug: 	has_quorum=1
ccm[32290]: 2007/10/19_11:27:16 debug: 	nodename=prec370e bornon=1
crmd[32295]: 2007/10/19_11:27:16 notice: populate_cib_nodes: Node: prec370d (uuid: 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6)
lrmd[32292]: 2007/10/19_11:27:16 debug: on_msg_register:client crmd [32295] registered
crmd[32295]: 2007/10/19_11:27:16 info: do_ha_control: Connected to Heartbeat
mgmtd[32296]: 2007/10/19_11:27:16 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:16 debug: do_fsa_action: actions:trace: 	// A_READCONFIG
cib[32298]: 2007/10/19_11:27:16 debug: write_cib_contents: Archiving current version
crmd[32295]: 2007/10/19_11:27:16 debug: do_fsa_action: actions:trace: 	// A_LRM_CONNECT
crmd[32295]: 2007/10/19_11:27:16 debug: do_lrm_control: Connecting to the LRM
crmd[32295]: 2007/10/19_11:27:16 debug: do_lrm_control: LRM connection established
crmd[32295]: 2007/10/19_11:27:16 debug: do_fsa_action: actions:trace: 	// A_CCM_CONNECT
crmd[32295]: 2007/10/19_11:27:16 info: do_ccm_control: CCM connection established... waiting for first callback
crmd[32295]: 2007/10/19_11:27:16 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[32295]: 2007/10/19_11:27:16 info: do_started: Delaying start, CCM (0000000000100000) not connected
cib[32298]: 2007/10/19_11:27:16 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
crmd[32295]: 2007/10/19_11:27:16 debug: register_fsa_input_adv: do_started prepended FSA input 2 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
crmd[32295]: 2007/10/19_11:27:16 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
crmd[32295]: 2007/10/19_11:27:16 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
crmd[32295]: 2007/10/19_11:27:16 debug: fsa_dump_inputs: Added input: 0000000000000100 (R_CIB_CONNECTED)
crmd[32295]: 2007/10/19_11:27:16 debug: fsa_dump_inputs: Added input: 0000000000000800 (R_LRM_CONNECTED)
crmd[32295]: 2007/10/19_11:27:16 info: crmd_init: Starting crmd's mainloop
cib[32298]: 2007/10/19_11:27:16 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
crmd[32295]: 2007/10/19_11:27:16 notice: crmd_client_status_callback: Status update: Client prec370e/crmd now has status [online]
cib[32298]: 2007/10/19_11:27:16 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
cib[32298]: 2007/10/19_11:27:16 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32298]: 2007/10/19_11:27:16 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32298]: 2007/10/19_11:27:16 debug: write_cib_contents: Verified CIB archive
cib[32298]: 2007/10/19_11:27:16 debug: write_cib_contents: Wrote CIB to disk
cib[32298]: 2007/10/19_11:27:16 info: write_cib_contents: Wrote version 0.1.1 of the CIB to disk (digest: 8bee196b4014e468fa84cf7c6317f8ae)
cib[32298]: 2007/10/19_11:27:16 debug: write_cib_contents: Wrote digest to disk
cib[32298]: 2007/10/19_11:27:16 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32298]: 2007/10/19_11:27:16 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32298]: 2007/10/19_11:27:16 debug: write_cib_contents: Wrote and verified CIB
ccm[32290]: 2007/10/19_11:27:17 debug: recv msg CCM_TYPE_ALIVE from prec370d, status:[null ptr]
ccm[32290]: 2007/10/19_11:27:17 debug: quorum plugin: majority
crmd[32295]: 2007/10/19_11:27:17 notice: crmd_client_status_callback: Status update: Client prec370e/crmd now has status [online]
cib[32291]: 2007/10/19_11:27:17 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
ccm[32290]: 2007/10/19_11:27:17 debug: cluster:linux-ha, member_count=2, member_quorum_votes=200
cib[32291]: 2007/10/19_11:27:17 info: mem_handle_event: no mbr_track info
ccm[32290]: 2007/10/19_11:27:17 debug: total_node_count=2, total_quorum_votes=200
cib[32291]: 2007/10/19_11:27:17 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[32290]: 2007/10/19_11:27:17 debug: send msg CCM_TYPE_MEM_LIST to cluster, status:[null]
cib[32291]: 2007/10/19_11:27:17 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
ccm[32290]: 2007/10/19_11:27:17 debug: dump current membership 0x2a959cf028
cib[32291]: 2007/10/19_11:27:17 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=2)
ccm[32290]: 2007/10/19_11:27:17 debug: 	leader=prec370e
cib[32291]: 2007/10/19_11:27:17 debug: set_transition: CCM transition: old=1, new=2
ccm[32290]: 2007/10/19_11:27:17 debug: 	transition=2
cib[32291]: 2007/10/19_11:27:17 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
ccm[32290]: 2007/10/19_11:27:17 debug: 	status=CCM_STATE_JOINED
cib[32291]: 2007/10/19_11:27:17 info: cib_ccm_msg_callback: PEER: prec370e
ccm[32290]: 2007/10/19_11:27:17 debug: 	has_quorum=1
cib[32291]: 2007/10/19_11:27:17 info: cib_ccm_msg_callback: PEER: prec370d
mgmtd[32296]: 2007/10/19_11:27:17 debug: update cib finished
ccm[32290]: 2007/10/19_11:27:17 debug: 	nodename=prec370e bornon=1
cib[32291]: 2007/10/19_11:27:17 debug: update_cib_object: done
ccm[32290]: 2007/10/19_11:27:17 debug: 	nodename=prec370d bornon=2
ccm[32290]: 2007/10/19_11:27:17 debug: quorum is 1
ccm[32290]: 2007/10/19_11:27:17 debug: delivering new membership to 2 clients: 
ccm[32290]: 2007/10/19_11:27:17 debug: client: pid =32295
ccm[32290]: 2007/10/19_11:27:17 debug: client: pid =32291
ccm[32290]: 2007/10/19_11:27:17 debug: recv msg CCM_TYPE_MEM_LIST from prec370e, status:[null ptr]
ccm[32290]: 2007/10/19_11:27:17 WARN: ccm_state_joined: received message with unknown cookie, just dropping
ccm[32290]: 2007/10/19_11:27:17 debug: dump current membership 0x2a959cf028
crmd[32295]: 2007/10/19_11:27:17 notice: crmd_client_status_callback: Status update: Client prec370d/crmd now has status [online]
ccm[32290]: 2007/10/19_11:27:17 debug: 	leader=prec370e
ccm[32290]: 2007/10/19_11:27:17 debug: 	transition=2
ccm[32290]: 2007/10/19_11:27:17 debug: 	status=CCM_STATE_JOINED
ccm[32290]: 2007/10/19_11:27:17 debug: 	has_quorum=1
ccm[32290]: 2007/10/19_11:27:17 debug: 	nodename=prec370e bornon=1
cib[32291]: 2007/10/19_11:27:17 debug: update_cib_object: done
ccm[32290]: 2007/10/19_11:27:17 debug: 	nodename=prec370d bornon=2
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_STARTED
cib[32291]: 2007/10/19_11:27:17 debug: update_cib_object: done
crmd[32295]: 2007/10/19_11:27:17 info: do_started: Delaying start, CCM (0000000000100000) not connected
crmd[32295]: 2007/10/19_11:27:17 debug: register_fsa_input_adv: do_started prepended FSA input 3 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
crmd[32295]: 2007/10/19_11:27:17 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
crmd[32295]: 2007/10/19_11:27:17 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
crmd[32295]: 2007/10/19_11:27:17 debug: config_query_callback: Call 4 : Parsing CIB options
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
crmd[32295]: 2007/10/19_11:27:17 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
crmd[32295]: 2007/10/19_11:27:17 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 4 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: no mbr_track info
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
crmd[32295]: 2007/10/19_11:27:17 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
crmd[32295]: 2007/10/19_11:27:17 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
crmd[32295]: 2007/10/19_11:27:17 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 5 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
crmd[32295]: 2007/10/19_11:27:17 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[32295]: 2007/10/19_11:27:17 debug: do_ccm_update_cache: Updating cache after CCM event 2 (NEW MEMBERSHIP).
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: NEW MEMBERSHIP: trans=2, nodes=2, new=1, lost=0 n_idx=0, new_idx=2, old_idx=4
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: 	CURRENT: prec370e [nodeid=1, born=1]
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: 	CURRENT: prec370d [nodeid=0, born=2]
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: 	NEW:     prec370d [nodeid=0, born=2]
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[32295]: 2007/10/19_11:27:17 info: do_started: The local CRM is operational
crmd[32295]: 2007/10/19_11:27:17 debug: register_fsa_input_adv: do_started appended FSA input 6 (I_PENDING) (cause=C_CCM_CALLBACK) without data
crmd[32295]: 2007/10/19_11:27:17 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[32295]: 2007/10/19_11:27:17 debug: do_ccm_update_cache: Ignoring superceeded NEW MEMBERSHIP CCM event 1 - we had 2
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: NEW MEMBERSHIP: trans=1, nodes=1, new=1, lost=0 n_idx=0, new_idx=0, old_idx=3
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: 	CURRENT: prec370e [nodeid=1, born=1]
crmd[32295]: 2007/10/19_11:27:17 info: ccm_event_detail: 	NEW:     prec370e [nodeid=1, born=1]
crmd[32295]: 2007/10/19_11:27:17 debug: s_crmd_fsa: Processing I_PENDING: [ state=S_STARTING cause=C_CCM_CALLBACK origin=do_started ]
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:17 info: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_CCM_CALLBACK origin=do_started ]
crmd[32295]: 2007/10/19_11:27:17 info: update_dc: Set DC to <null> (<null>)
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:17 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_QUERY
mgmtd[32296]: 2007/10/19_11:27:17 debug: update cib finished
mgmtd[32296]: 2007/10/19_11:27:17 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:18 debug: do_cl_join_query: Querying for a DC
crmd[32295]: 2007/10/19_11:27:18 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_START
crmd[32295]: 2007/10/19_11:27:18 debug: crm_timer_start: Started Election Trigger (I_DC_TIMEOUT:10000ms), src=10
crmd[32295]: 2007/10/19_11:27:18 debug: fsa_dump_inputs: Added input: 0000000000100000 (R_CCM_DATA)
crmd[32295]: 2007/10/19_11:27:18 debug: ccm_node_update_complete: Node update 8 complete
attrd[32294]: 2007/10/19_11:27:19 info: main: Starting mainloop...
crmd[32295]: 2007/10/19_11:27:28 info: crm_timer_popped: Election Trigger (I_DC_TIMEOUT) just popped!
crmd[32295]: 2007/10/19_11:27:28 debug: crm_timer_stop: Stopping Election Trigger (I_DC_TIMEOUT:10000ms), src=10
crmd[32295]: 2007/10/19_11:27:28 debug: register_fsa_input_adv: crm_timer_popped appended FSA input 7 (I_DC_TIMEOUT) (cause=C_TIMER_POPPED) without data
crmd[32295]: 2007/10/19_11:27:28 debug: s_crmd_fsa: Processing I_DC_TIMEOUT: [ state=S_PENDING cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_WARN  
crmd[32295]: 2007/10/19_11:27:28 WARN: do_log: [[FSA]] Input I_DC_TIMEOUT from crm_timer_popped() received in state (S_PENDING)
crmd[32295]: 2007/10/19_11:27:28 info: do_state_transition: State transition S_PENDING -> S_ELECTION [ input=I_DC_TIMEOUT cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[32295]: 2007/10/19_11:27:28 info: update_dc: Set DC to <null> (<null>)
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_vote: Destroying voted hash
crmd[32295]: 2007/10/19_11:27:28 debug: crm_timer_start: Started Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[32295]: 2007/10/19_11:27:28 debug: register_fsa_input_adv: handle_request appended FSA input 8 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:28 debug: register_fsa_input_adv: handle_request appended FSA input 9 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Created voted hash
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Election 2, owner: 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6
crmd[32295]: 2007/10/19_11:27:28 info: do_election_count_vote: Election check: vote from prec370d
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Election pass: born_on
crmd[32295]: 2007/10/19_11:27:28 info: do_election_count_vote: Election won over prec370d
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Destroying voted hash
crmd[32295]: 2007/10/19_11:27:28 debug: register_fsa_input_adv: do_election_count_vote appended FSA input 10 (I_ELECTION) (cause=C_FSA_INTERNAL) without data
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32295]: 2007/10/19_11:27:28 info: do_election_check: Still waiting on 2 non-votes (2 total)
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Created voted hash
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_count_vote: Election 2, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[32295]: 2007/10/19_11:27:28 info: do_election_count_vote: Updated voted hash for prec370e to vote
crmd[32295]: 2007/10/19_11:27:28 info: do_election_count_vote: Election ignore: our vote (prec370e)
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32295]: 2007/10/19_11:27:28 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[32295]: 2007/10/19_11:27:28 debug: s_crmd_fsa: Processing I_ELECTION: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_count_vote ]
crmd[32295]: 2007/10/19_11:27:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[32295]: 2007/10/19_11:27:28 debug: do_election_vote: Destroying voted hash
crmd[32295]: 2007/10/19_11:27:28 debug: crm_timer_start: Election Timeout (I_ELECTION_DC:120000ms) already running: src=11
crmd[32295]: 2007/10/19_11:27:29 debug: register_fsa_input_adv: handle_request appended FSA input 11 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:29 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32295]: 2007/10/19_11:27:29 debug: do_election_count_vote: Created voted hash
crmd[32295]: 2007/10/19_11:27:29 debug: do_election_count_vote: Election 3, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[32295]: 2007/10/19_11:27:29 info: do_election_count_vote: Updated voted hash for prec370e to vote
crmd[32295]: 2007/10/19_11:27:29 info: do_election_count_vote: Election ignore: our vote (prec370e)
crmd[32295]: 2007/10/19_11:27:29 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32295]: 2007/10/19_11:27:29 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[32295]: 2007/10/19_11:27:29 debug: register_fsa_input_adv: handle_request appended FSA input 12 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:29 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32295]: 2007/10/19_11:27:29 debug: do_election_count_vote: Election 2, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[32295]: 2007/10/19_11:27:29 debug: do_election_count_vote: Ignore old 'no-vote' from prec370d: 2 vs. 3
crmd[32295]: 2007/10/19_11:27:29 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32295]: 2007/10/19_11:27:29 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[32295]: 2007/10/19_11:27:30 debug: register_fsa_input_adv: handle_request appended FSA input 13 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32295]: 2007/10/19_11:27:30 debug: do_election_count_vote: Election 3, owner: 9d9ca527-cea9-470c-9e03-e49fe5630bba
crmd[32295]: 2007/10/19_11:27:30 info: do_election_count_vote: Updated voted hash for prec370d to no-vote
crmd[32295]: 2007/10/19_11:27:30 info: do_election_count_vote: Election ignore: no-vote from prec370d
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32295]: 2007/10/19_11:27:30 debug: crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[32295]: 2007/10/19_11:27:30 debug: register_fsa_input_adv: do_election_check appended FSA input 14 (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
crmd[32295]: 2007/10/19_11:27:30 debug: do_election_check: Destroying voted hash
crmd[32295]: 2007/10/19_11:27:30 debug: s_crmd_fsa: Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:30 info: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_TE_START
crmd[32295]: 2007/10/19_11:27:30 info: start_subsystem: Starting sub-system "tengine"
crmd[32299]: 2007/10/19_11:27:30 debug: start_subsystem: Executing "/usr/lib64/heartbeat/tengine (tengine)" (pid 32299)
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_PE_START
cib[32291]: 2007/10/19_11:27:30 info: cib_process_readwrite: We are now in R/W mode
crmd[32295]: 2007/10/19_11:27:30 info: start_subsystem: Starting sub-system "pengine"
crmd[32300]: 2007/10/19_11:27:30 debug: start_subsystem: Executing "/usr/lib64/heartbeat/pengine (pengine)" (pid 32300)
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_START
crmd[32295]: 2007/10/19_11:27:30 debug: crm_timer_start: Started Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_DC_TAKEOVER
crmd[32295]: 2007/10/19_11:27:30 info: do_dc_takeover: Taking over DC status for this partition
cib[32291]: 2007/10/19_11:27:30 debug: log_data_element: cib:diff: - <cib num_updates="1"/>
mgmtd[32296]: 2007/10/19_11:27:30 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:30 info: G_main_add_SignalHandler: Added signal handler for signal 15
cib[32291]: 2007/10/19_11:27:30 debug: log_data_element: cib:diff: + <cib num_updates="2"/>
tengine[32299]: 2007/10/19_11:27:30 info: G_main_add_TriggerHandler: Added signal manual handler
cib[32291]: 2007/10/19_11:27:30 debug: send_peer_reply: Sending update diff 0.1.1 -> 0.1.2
tengine[32299]: 2007/10/19_11:27:30 info: G_main_add_TriggerHandler: Added signal manual handler
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_OFFER_ALL
crmd[32295]: 2007/10/19_11:27:30 debug: initialize_join: join-1: Initializing join data (flag=true)
crmd[32295]: 2007/10/19_11:27:30 info: update_dc: Set DC to <null> (<null>)
crmd[32295]: 2007/10/19_11:27:30 info: join_make_offer: Making join offers based on membership 2
crmd[32295]: 2007/10/19_11:27:30 debug: join_make_offer: join-1: Sending offer to prec370d
crmd[32295]: 2007/10/19_11:27:30 debug: join_make_offer: join-1: Sending offer to prec370e
crmd[32295]: 2007/10/19_11:27:30 info: do_dc_join_offer_all: join-1: Waiting on 2 outstanding join acks
crmd[32295]: 2007/10/19_11:27:30 debug: fsa_dump_inputs: Added input: 0000000000000001 (R_THE_DC)
crmd[32295]: 2007/10/19_11:27:30 debug: fsa_dump_inputs: Added input: 0000000000000010 (R_JOIN_OK)
crmd[32295]: 2007/10/19_11:27:30 debug: fsa_dump_inputs: Added input: 0000000000000080 (R_INVOKE_PE)
crmd[32295]: 2007/10/19_11:27:30 debug: fsa_dump_inputs: Added input: 0000000000002000 (R_PE_REQUIRED)
pengine[32300]: 2007/10/19_11:27:30 info: G_main_add_SignalHandler: Added signal handler for signal 15
crmd[32295]: 2007/10/19_11:27:30 debug: fsa_dump_inputs: Added input: 0000000000004000 (R_TE_REQUIRED)
pengine[32300]: 2007/10/19_11:27:30 debug: main: HA_record_pengine_inputs = on
pengine[32300]: 2007/10/19_11:27:30 info: pe_init: Starting pengine
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: - <cib epoch="1" num_updates="2"/>
mgmtd[32296]: 2007/10/19_11:27:30 debug: update cib finished
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: + <cib epoch="2" num_updates="1">
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +   <configuration>
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +     <crm_config>
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +       <cluster_property_set id="cib-bootstrap-options">
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +         <attributes>
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +           <nvpair id="cib-bootstrap-options-dc-version" name="dc-version" value="2.1.3-2cff5374f61b tip"/>
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +         </attributes>
tengine[32299]: 2007/10/19_11:27:30 debug: cib_native_signon: Connection to CIB successful
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +       </cluster_property_set>
tengine[32299]: 2007/10/19_11:27:30 info: te_init: Registering TE UUID: 32efb8b1-869d-45bf-a401-30b577f14ead
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +     </crm_config>
tengine[32299]: 2007/10/19_11:27:30 info: set_graph_functions: Setting custom graph functions
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: +   </configuration>
tengine[32299]: 2007/10/19_11:27:30 info: unpack_graph: Unpacked transition -1: 0 actions in 0 synapses
cib[32291]: 2007/10/19_11:27:30 info: log_data_element: cib:diff: + </cib>
tengine[32299]: 2007/10/19_11:27:30 info: te_init: Starting tengine
cib[32291]: 2007/10/19_11:27:30 debug: send_peer_reply: Sending update diff 0.1.2 -> 0.2.1
tengine[32299]: 2007/10/19_11:27:30 info: te_connect_stonith: Attempting connection to fencing daemon...
cib[32301]: 2007/10/19_11:27:30 debug: write_cib_contents: Archiving current version
cib[32291]: 2007/10/19_11:27:30 info: cib_null_callback: Setting cib_diff_notify callbacks for tengine: on
cib[32301]: 2007/10/19_11:27:30 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32301]: 2007/10/19_11:27:30 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[32301]: 2007/10/19_11:27:30 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
cib[32301]: 2007/10/19_11:27:30 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32301]: 2007/10/19_11:27:30 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32301]: 2007/10/19_11:27:30 debug: write_cib_contents: Verified CIB archive
cib[32301]: 2007/10/19_11:27:30 debug: write_cib_contents: Wrote CIB to disk
cib[32301]: 2007/10/19_11:27:30 info: write_cib_contents: Wrote version 0.2.1 of the CIB to disk (digest: 474eb301bf2c328d226fa25da1d35e13)
cib[32301]: 2007/10/19_11:27:30 debug: write_cib_contents: Wrote digest to disk
cib[32301]: 2007/10/19_11:27:30 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32301]: 2007/10/19_11:27:30 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32301]: 2007/10/19_11:27:30 debug: write_cib_contents: Wrote and verified CIB
crmd[32295]: 2007/10/19_11:27:30 debug: handle_request: Raising I_JOIN_OFFER: join-1
crmd[32295]: 2007/10/19_11:27:30 debug: register_fsa_input_adv: route_message appended FSA input 15 (I_JOIN_OFFER) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:30 debug: s_crmd_fsa: Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_REQUEST
crmd[32295]: 2007/10/19_11:27:30 info: update_dc: Set DC to prec370e (2.0)
crmd[32295]: 2007/10/19_11:27:30 debug: do_cl_join_offer_respond: do_cl_join_offer_respond added action A_DC_TIMER_STOP to the FSA
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:30 debug: join_query_callback: Respond to join offer join-1
crmd[32295]: 2007/10/19_11:27:30 debug: join_query_callback: Acknowledging prec370e as our DC
crmd[32295]: 2007/10/19_11:27:30 debug: register_fsa_input_adv: route_message appended FSA input 16 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:30 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:30 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32295]: 2007/10/19_11:27:30 debug: do_dc_join_filter_offer: Processing req from prec370e
crmd[32295]: 2007/10/19_11:27:30 debug: do_dc_join_filter_offer: join-1: Welcoming node prec370e (ref join_request-crmd-1192760850-9)
crmd[32295]: 2007/10/19_11:27:30 debug: do_dc_join_filter_offer: 1 nodes have been integrated into join-1
crmd[32295]: 2007/10/19_11:27:30 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32295]: 2007/10/19_11:27:30 debug: do_dc_join_filter_offer: join-1: Still waiting on 1 outstanding offers
tengine[32299]: 2007/10/19_11:27:31 debug: stonithd_signon: creating connection
tengine[32299]: 2007/10/19_11:27:31 debug: sending out the signon msg.
stonithd[32293]: 2007/10/19_11:27:31 debug: client tengine (pid=32299) succeeded to signon to stonithd.
tengine[32299]: 2007/10/19_11:27:31 debug: signed on to stonithd.
tengine[32299]: 2007/10/19_11:27:31 info: te_connect_stonith: Connected
crmd[32295]: 2007/10/19_11:27:31 debug: register_fsa_input_adv: route_message appended FSA input 17 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:31 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32295]: 2007/10/19_11:27:31 debug: do_dc_join_filter_offer: Processing req from prec370d
crmd[32295]: 2007/10/19_11:27:31 debug: do_dc_join_filter_offer: join-1: Welcoming node prec370d (ref join_request-crmd-1192760850-5)
crmd[32295]: 2007/10/19_11:27:31 debug: do_dc_join_filter_offer: 2 nodes have been integrated into join-1
crmd[32295]: 2007/10/19_11:27:31 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32295]: 2007/10/19_11:27:31 debug: check_join_state: join-1: Integration of 2 peers complete: do_dc_join_filter_offer
crmd[32295]: 2007/10/19_11:27:31 debug: register_fsa_input_adv: check_join_state prepended FSA input 18 (I_INTEGRATED) (cause=C_FSA_INTERNAL) without data
cib[32291]: 2007/10/19_11:27:31 info: sync_our_cib: Syncing CIB to all peers
crmd[32295]: 2007/10/19_11:27:31 debug: s_crmd_fsa: Processing I_INTEGRATED: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32295]: 2007/10/19_11:27:31 info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32295]: 2007/10/19_11:27:31 info: do_state_transition: All 2 cluster nodes responded to the join offer.
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:31 debug: crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_START
crmd[32295]: 2007/10/19_11:27:31 debug: crm_timer_start: Started Finalization Timer (I_ELECTION:600000ms), src=15
attrd[32294]: 2007/10/19_11:27:31 info: attrd_local_callback: Sending full refresh
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_FINALIZE
crmd[32295]: 2007/10/19_11:27:31 debug: do_dc_join_finalize: Finializing join-1 for 2 clients
crmd[32295]: 2007/10/19_11:27:31 info: update_attrd: Connecting to attrd...
crmd[32295]: 2007/10/19_11:27:31 debug: update_attrd: sent attrd refresh
crmd[32295]: 2007/10/19_11:27:31 debug: check_join_state: Invoked by do_dc_join_finalize in state: S_FINALIZE_JOIN
crmd[32295]: 2007/10/19_11:27:31 debug: check_join_state: join-1: Still waiting on 2 integrated nodes
crmd[32295]: 2007/10/19_11:27:31 debug: finalize_join: Notifying 2 clients of join-1 results
crmd[32295]: 2007/10/19_11:27:31 debug: finalize_join_for: join-1: ACK'ing join request from prec370d, state member
crmd[32295]: 2007/10/19_11:27:31 debug: finalize_join_for: join-1: ACK'ing join request from prec370e, state member
crmd[32295]: 2007/10/19_11:27:31 debug: fsa_dump_inputs: Added input: 0000000000020000 (R_HAVE_CIB)
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: - <cib num_updates="1" generated="false"/>
mgmtd[32296]: 2007/10/19_11:27:31 debug: update cib finished
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: + <cib num_updates="2" generated="true" dc_uuid="9d9ca527-cea9-470c-9e03-e49fe5630bba"/>
cib[32291]: 2007/10/19_11:27:31 debug: send_peer_reply: Sending update diff 0.2.1 -> 0.2.2
tengine[32299]: 2007/10/19_11:27:31 debug: te_update_diff: Processing diff (cib_update): 0.2.1 -> 0.2.2
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: - <cib num_updates="2"/>
mgmtd[32296]: 2007/10/19_11:27:31 debug: update cib finished
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: + <cib num_updates="3"/>
tengine[32299]: 2007/10/19_11:27:31 debug: te_update_diff: Processing diff (cib_update): 0.2.2 -> 0.2.3
cib[32291]: 2007/10/19_11:27:31 debug: send_peer_reply: Sending update diff 0.2.2 -> 0.2.3
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: - <cib num_updates="3"/>
mgmtd[32296]: 2007/10/19_11:27:31 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:31 debug: te_update_diff: Processing diff (cib_update): 0.2.3 -> 0.2.4
cib[32291]: 2007/10/19_11:27:31 debug: log_data_element: cib:diff: + <cib num_updates="4"/>
cib[32291]: 2007/10/19_11:27:31 debug: send_peer_reply: Sending update diff 0.2.3 -> 0.2.4
crmd[32295]: 2007/10/19_11:27:31 debug: handle_request: Raising I_JOIN_RESULT: join-1
crmd[32295]: 2007/10/19_11:27:31 debug: register_fsa_input_adv: route_message appended FSA input 19 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:31 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32295]: 2007/10/19_11:27:31 info: update_dc: Set DC to prec370e (2.0)
crmd[32295]: 2007/10/19_11:27:31 debug: do_cl_join_finalize_respond: Confirming join join-1: join_ack_nack
crmd[32295]: 2007/10/19_11:27:31 debug: do_cl_join_finalize_respond: join-1: Join complete.  Sending local LRM status.
crmd[32295]: 2007/10/19_11:27:31 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32295]: 2007/10/19_11:27:31 debug: do_dc_join_ack: Ignoring op=join_ack_nack message
crmd[32295]: 2007/10/19_11:27:32 debug: register_fsa_input_adv: route_message appended FSA input 20 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:32 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32295]: 2007/10/19_11:27:32 info: do_dc_join_ack: join-1: Updating node state to member for prec370d
crmd[32295]: 2007/10/19_11:27:32 debug: do_dc_join_ack: join-1: Registered callback for LRM update 20
cib[32291]: 2007/10/19_11:27:32 debug: update_cib_object: done
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: - <cib num_updates="4"/>
mgmtd[32296]: 2007/10/19_11:27:32 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:32 debug: join_update_complete_callback: Join update 20 complete
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + <cib num_updates="5">
crmd[32295]: 2007/10/19_11:27:32 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   <status>
crmd[32295]: 2007/10/19_11:27:32 debug: check_join_state: join-1: Still waiting on 1 confirmations
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     <node_state ha="active" join="member" expected="member" shutdown="0" id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:32 debug: te_update_diff: Processing diff (cib_update): 0.2.4 -> 0.2.5
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         <lrm_resources/>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:32 debug: send_peer_reply: Sending update diff 0.2.4 -> 0.2.5
crmd[32295]: 2007/10/19_11:27:32 debug: register_fsa_input_adv: route_message appended FSA input 21 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:32 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32295]: 2007/10/19_11:27:32 info: do_dc_join_ack: join-1: Updating node state to member for prec370e
crmd[32295]: 2007/10/19_11:27:32 debug: do_dc_join_ack: join-1: Registered callback for LRM update 21
cib[32291]: 2007/10/19_11:27:32 debug: update_cib_object: done
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: - <cib num_updates="5"/>
mgmtd[32296]: 2007/10/19_11:27:32 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:32 debug: join_update_complete_callback: Join update 21 complete
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + <cib num_updates="6">
crmd[32295]: 2007/10/19_11:27:32 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   <status>
crmd[32295]: 2007/10/19_11:27:32 debug: check_join_state: join-1 complete: join_update_complete_callback
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     <node_state ha="active" join="member" expected="member" id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[32295]: 2007/10/19_11:27:32 debug: register_fsa_input_adv: check_join_state appended FSA input 22 (I_FINALIZED) (cause=C_FSA_INTERNAL) without data
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[32295]: 2007/10/19_11:27:32 debug: s_crmd_fsa: Processing I_FINALIZED: [ state=S_FINALIZE_JOIN cause=C_FSA_INTERNAL origin=check_join_state ]
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         <lrm_resources/>
crmd[32295]: 2007/10/19_11:27:32 info: do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ]
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       </lrm>
tengine[32299]: 2007/10/19_11:27:32 info: update_abort_priority: Abort priority upgraded to 1000000
crmd[32295]: 2007/10/19_11:27:32 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     </node_state>
tengine[32299]: 2007/10/19_11:27:32 info: update_abort_priority: 'DC Takeover' abort superceeded
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   </status>
tengine[32299]: 2007/10/19_11:27:32 debug: abort_transition_graph: process_te_message:277 - Triggered graph processing : Peer Cancelled
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + </cib>
tengine[32299]: 2007/10/19_11:27:32 debug: notify_crmd: Transition -1 status: te_abort - Peer Cancelled
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:32 debug: send_peer_reply: Sending update diff 0.2.5 -> 0.2.6
tengine[32299]: 2007/10/19_11:27:32 debug: print_graph: ## Empty transition graph ##
crmd[32295]: 2007/10/19_11:27:32 debug: crm_timer_stop: Stopping Finalization Timer (I_ELECTION:600000ms), src=15
tengine[32299]: 2007/10/19_11:27:32 debug: te_update_diff: Processing diff (cib_update): 0.2.5 -> 0.2.6
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_TE_CANCEL
crmd[32295]: 2007/10/19_11:27:32 debug: do_te_invoke: Cancelling the active Transition
crmd[32295]: 2007/10/19_11:27:32 debug: handle_request: Transition cancelled: te_abort/Peer Cancelled
crmd[32295]: 2007/10/19_11:27:32 debug: register_fsa_input_adv: route_message appended FSA input 23 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:32 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
crmd[32295]: 2007/10/19_11:27:32 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
crmd[32295]: 2007/10/19_11:27:32 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1192760852-14
pengine[32300]: 2007/10/19_11:27:32 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[32300]: 2007/10/19_11:27:32 debug: unpack_config: Default action timeout: 120s
pengine[32300]: 2007/10/19_11:27:32 debug: unpack_config: Default stickiness: 1000000
pengine[32300]: 2007/10/19_11:27:32 debug: unpack_config: Default failure stickiness: -1000000
pengine[32300]: 2007/10/19_11:27:32 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32300]: 2007/10/19_11:27:32 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32300]: 2007/10/19_11:27:32 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32300]: 2007/10/19_11:27:32 info: determine_online_status: Node prec370e is online
pengine[32300]: 2007/10/19_11:27:32 info: determine_online_status: Node prec370d is online
pengine[32300]: 2007/10/19_11:27:32 notice: group_print: Resource Group: grpDummy
pengine[32300]: 2007/10/19_11:27:32 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:32 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:32 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[32300]: 2007/10/19_11:27:32 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[32300]: 2007/10/19_11:27:32 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[32300]: 2007/10/19_11:27:32 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 300
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[32300]: 2007/10/19_11:27:32 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[32300]: 2007/10/19_11:27:32 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[32300]: 2007/10/19_11:27:32 debug: native_assign_node: Assigning prec370e to prmDummyB
pengine[32300]: 2007/10/19_11:27:32 notice: StartRsc:  prec370e	Start prmDummyA
pengine[32300]: 2007/10/19_11:27:32 notice: RecurringOp: prec370e	   prmDummyA_monitor_10000
pengine[32300]: 2007/10/19_11:27:32 notice: StartRsc:  prec370e	Start prmDummyB
pengine[32300]: 2007/10/19_11:27:32 notice: RecurringOp: prec370e	   prmDummyB_monitor_10000
pengine[32300]: 2007/10/19_11:27:32 debug: update_action:       Ignoring implies left - prmDummyB already stopped
pengine[32300]: 2007/10/19_11:27:32 debug: get_last_sequence: Series file /var/lib/heartbeat/pengine/pe-input.last does not exist
crmd[32295]: 2007/10/19_11:27:32 debug: register_fsa_input_adv: route_message appended FSA input 24 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:32 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:32 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:32 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
crmd[32295]: 2007/10/19_11:27:32 debug: do_te_invoke: Starting a transition
tengine[32299]: 2007/10/19_11:27:32 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-0.bz2
tengine[32299]: 2007/10/19_11:27:32 info: unpack_graph: Unpacked transition 0: 13 actions in 13 synapses
tengine[32299]: 2007/10/19_11:27:32 debug: initiate_action: Action 3: Increasing IDLE timer to 240000
tengine[32299]: 2007/10/19_11:27:32 info: send_rsc_command: Initiating action 3: prmDummyA_monitor_0 on prec370e
tengine[32299]: 2007/10/19_11:27:32 debug: send_rsc_command: Action 3: Increasing transition 0 timeout to 360000 (2*120000 + 120000)
tengine[32299]: 2007/10/19_11:27:32 info: send_rsc_command: Initiating action 6: prmDummyA_monitor_0 on prec370d
tengine[32299]: 2007/10/19_11:27:32 info: send_rsc_command: Initiating action 4: prmDummyB_monitor_0 on prec370e
tengine[32299]: 2007/10/19_11:27:32 info: send_rsc_command: Initiating action 7: prmDummyB_monitor_0 on prec370d
tengine[32299]: 2007/10/19_11:27:32 debug: run_graph: Transition 0: (Complete=0, Pending=0, Fired=4, Skipped=0, Incomplete=9)
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_add_rsc:client [32295] adds resource prmDummyA
crmd[32295]: 2007/10/19_11:27:32 debug: get_lrm_resource: Adding rsc prmDummyA before operation
crmd[32295]: 2007/10/19_11:27:32 info: do_lrm_rsc_op: Performing op=prmDummyA_monitor_0 key=3:0:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_perform_op: add an operation operation monitor[2] on ocf::Dummy::prmDummyA for client 32295, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[32292]: 2007/10/19_11:27:32 info: rsc:prmDummyA: monitor
pengine[32300]: 2007/10/19_11:27:32 info: process_pe_message: Transition 0: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-0.bz2
crmd[32295]: 2007/10/19_11:27:32 debug: do_lrm_rsc_op: Recording pending op: 2 - prmDummyA_monitor_0 prmDummyA:2
crmd[32295]: 2007/10/19_11:27:32 debug: get_lrm_resource: Adding rsc prmDummyB before operation
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_add_rsc:client [32295] adds resource prmDummyB
crmd[32295]: 2007/10/19_11:27:32 info: do_lrm_rsc_op: Performing op=prmDummyB_monitor_0 key=4:0:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
lrmd[32292]: 2007/10/19_11:27:32 debug: on_msg_perform_op: add an operation operation monitor[3] on ocf::Dummy::prmDummyB for client 32295, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[32292]: 2007/10/19_11:27:32 info: rsc:prmDummyB: monitor
crmd[32295]: 2007/10/19_11:27:32 debug: do_lrm_rsc_op: Recording pending op: 3 - prmDummyB_monitor_0 prmDummyB:3
Dummy[32302][32314]: 2007/10/19_11:27:32 DEBUG: prmDummyA monitor : 7
lrmd[32292]: 2007/10/19_11:27:32 WARN: Exiting prmDummyA:monitor process 32302 returned rc 7.
crmd[32295]: 2007/10/19_11:27:32 info: process_lrm_event: LRM operation prmDummyA_monitor_0 (call=2, rc=7) complete 
crmd[32295]: 2007/10/19_11:27:32 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_monitor_0 (0:7;3:0:32efb8b1-869d-45bf-a401-30b577f14ead)

cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: - <cib num_updates="6"/>
mgmtd[32296]: 2007/10/19_11:27:32 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:32 debug: log_data_element: build_operation_update: digest:source <parameters/>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + <cib num_updates="7">
crmd[32295]: 2007/10/19_11:27:32 debug: do_update_resource: Sent resource state update message: 23
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   <status>
crmd[32295]: 2007/10/19_11:27:32 debug: process_lrm_event: Op prmDummyA_monitor_0 (call=2): Confirmed
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
crmd[32295]: 2007/10/19_11:27:32 debug: cib_rsc_callback: Resource update 23 complete
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
Dummy[32303][32315]: 2007/10/19_11:27:32 DEBUG: prmDummyB monitor : 7
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA" type="Dummy" class="ocf" provider="heartbeat">
cib[32291]: 2007/10/19_11:27:32 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;3:0:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="2" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:32 debug: send_peer_reply: Sending update diff 0.2.6 -> 0.2.7
lrmd[32292]: 2007/10/19_11:27:32 WARN: Exiting prmDummyB:monitor process 32303 returned rc 7.
tengine[32299]: 2007/10/19_11:27:32 debug: te_update_diff: Processing diff (cib_update): 0.2.6 -> 0.2.7
tengine[32299]: 2007/10/19_11:27:32 info: match_graph_event: Action prmDummyA_monitor_0 (3) confirmed on prec370e (rc=0)
tengine[32299]: 2007/10/19_11:27:32 debug: run_graph: Transition 0: (Complete=1, Pending=3, Fired=0, Skipped=0, Incomplete=9)
crmd[32295]: 2007/10/19_11:27:32 info: process_lrm_event: LRM operation prmDummyB_monitor_0 (call=3, rc=7) complete 
crmd[32295]: 2007/10/19_11:27:32 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_monitor_0 (0:7;4:0:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:27:32 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:27:32 debug: do_update_resource: Sent resource state update message: 24
crmd[32295]: 2007/10/19_11:27:32 debug: process_lrm_event: Op prmDummyB_monitor_0 (call=3): Confirmed
crmd[32295]: 2007/10/19_11:27:32 debug: cib_rsc_callback: Resource update 24 complete
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: - <cib num_updates="7"/>
mgmtd[32296]: 2007/10/19_11:27:32 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:32 debug: te_update_diff: Processing diff (cib_update): 0.2.7 -> 0.2.8
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + <cib num_updates="8">
tengine[32299]: 2007/10/19_11:27:32 info: match_graph_event: Action prmDummyB_monitor_0 (4) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:32 info: send_rsc_command: Initiating action 2: probe_complete on prec370e
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:32 debug: send_rsc_command: Skipping wait for 2
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:32 debug: run_graph: Transition 0: (Complete=2, Pending=2, Fired=1, Skipped=0, Incomplete=8)
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[32299]: 2007/10/19_11:27:32 debug: run_graph: Transition 0: (Complete=3, Pending=2, Fired=0, Skipped=0, Incomplete=8)
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB" type="Dummy" class="ocf" provider="heartbeat">
cib[32291]: 2007/10/19_11:27:32 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;4:0:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="3" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:32 debug: send_peer_reply: Sending update diff 0.2.7 -> 0.2.8
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: - <cib num_updates="8"/>
mgmtd[32296]: 2007/10/19_11:27:32 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:32 debug: te_update_diff: Processing diff (cib_modify): 0.2.8 -> 0.2.9
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + <cib num_updates="9">
tengine[32299]: 2007/10/19_11:27:32 info: extract_event: Aborting on transient_attributes changes for 9d9ca527-cea9-470c-9e03-e49fe5630bba
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:32 info: update_abort_priority: Abort priority upgraded to 1000000
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:32 info: update_abort_priority: Abort action 0 superceeded by 2
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       <transient_attributes id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:32 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         <instance_attributes id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           <attributes>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +             <nvpair id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba-probe_complete" name="probe_complete" value="true"/>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause     <attributes>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +           </attributes>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-9d9ca527-cea9-470c-9e03-e49fe5630bba-probe_complete" name="probe_complete" value="true"/>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +         </instance_attributes>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +       </transient_attributes>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +     </node_state>
tengine[32299]: 2007/10/19_11:27:32 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: +   </status>
tengine[32299]: 2007/10/19_11:27:32 debug: run_graph: Transition 0: (Complete=3, Pending=2, Fired=0, Skipped=7, Incomplete=1)
cib[32291]: 2007/10/19_11:27:32 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:32 debug: send_peer_reply: Sending update diff 0.2.8 -> 0.2.9
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="9"/>
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="10">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB" type="Dummy" class="ocf" provider="heartbeat">
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;7:0:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="3" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.9 -> 0.2.10
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.9 -> 0.2.10
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyB_monitor_0 (7) confirmed on prec370d (rc=0)
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 0: (Complete=4, Pending=1, Fired=0, Skipped=7, Incomplete=1)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="10"/>
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="11">
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.10 -> 0.2.11
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyA_monitor_0 (6) confirmed on prec370d (rc=0)
crmd[32295]: 2007/10/19_11:27:34 debug: handle_request: Transition cancelled: te_abort/transient_attributes
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 5: probe_complete on prec370d
crmd[32295]: 2007/10/19_11:27:34 debug: register_fsa_input_adv: route_message appended FSA input 25 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:34 debug: send_rsc_command: Skipping wait for 5
crmd[32295]: 2007/10/19_11:27:34 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 0: (Complete=5, Pending=0, Fired=1, Skipped=7, Incomplete=0)
crmd[32295]: 2007/10/19_11:27:34 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA" type="Dummy" class="ocf" provider="heartbeat">
tengine[32299]: 2007/10/19_11:27:34 info: run_graph: ====================================================
crmd[32295]: 2007/10/19_11:27:34 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;6:0:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="2" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
tengine[32299]: 2007/10/19_11:27:34 notice: run_graph: Transition 0: (Complete=6, Pending=0, Fired=0, Skipped=7, Incomplete=0)
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
tengine[32299]: 2007/10/19_11:27:34 debug: notify_crmd: Transition 0 status: te_abort - transient_attributes
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
crmd[32295]: 2007/10/19_11:27:34 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.10 -> 0.2.11
crmd[32295]: 2007/10/19_11:27:34 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1192760854-16
pengine[32300]: 2007/10/19_11:27:34 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[32300]: 2007/10/19_11:27:34 debug: unpack_config: Default action timeout: 120s
pengine[32300]: 2007/10/19_11:27:34 debug: unpack_config: Default stickiness: 1000000
pengine[32300]: 2007/10/19_11:27:34 debug: unpack_config: Default failure stickiness: -1000000
pengine[32300]: 2007/10/19_11:27:34 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32300]: 2007/10/19_11:27:34 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32300]: 2007/10/19_11:27:34 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32300]: 2007/10/19_11:27:34 info: determine_online_status: Node prec370e is online
pengine[32300]: 2007/10/19_11:27:34 info: determine_online_status: Node prec370d is online
pengine[32300]: 2007/10/19_11:27:34 notice: group_print: Resource Group: grpDummy
pengine[32300]: 2007/10/19_11:27:34 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:34 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:34 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[32300]: 2007/10/19_11:27:34 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[32300]: 2007/10/19_11:27:34 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[32300]: 2007/10/19_11:27:34 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 300
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[32300]: 2007/10/19_11:27:34 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[32300]: 2007/10/19_11:27:34 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[32300]: 2007/10/19_11:27:34 debug: native_assign_node: Assigning prec370e to prmDummyB
pengine[32300]: 2007/10/19_11:27:34 notice: StartRsc:  prec370e	Start prmDummyA
pengine[32300]: 2007/10/19_11:27:34 notice: RecurringOp: prec370e	   prmDummyA_monitor_10000
pengine[32300]: 2007/10/19_11:27:34 notice: StartRsc:  prec370e	Start prmDummyB
pengine[32300]: 2007/10/19_11:27:34 notice: RecurringOp: prec370e	   prmDummyB_monitor_10000
pengine[32300]: 2007/10/19_11:27:34 debug: update_action:       Ignoring implies left - prmDummyB already stopped
crmd[32295]: 2007/10/19_11:27:34 debug: register_fsa_input_adv: route_message appended FSA input 26 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:34 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:34 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
crmd[32295]: 2007/10/19_11:27:34 debug: do_te_invoke: Starting a transition
pengine[32300]: 2007/10/19_11:27:34 info: process_pe_message: Transition 1: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-1.bz2
tengine[32299]: 2007/10/19_11:27:34 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-1.bz2
tengine[32299]: 2007/10/19_11:27:34 info: unpack_graph: Unpacked transition 1: 7 actions in 7 synapses
tengine[32299]: 2007/10/19_11:27:34 debug: initiate_action: Action 9: Increasing IDLE timer to 240000
tengine[32299]: 2007/10/19_11:27:34 info: te_pseudo_action: Pseudo action 9 fired and confirmed
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 5: prmDummyA_start_0 on prec370e
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 3: probe_complete on prec370d
crmd[32295]: 2007/10/19_11:27:34 info: do_lrm_rsc_op: Performing op=prmDummyA_start_0 key=5:1:32efb8b1-869d-45bf-a401-30b577f14ead)
tengine[32299]: 2007/10/19_11:27:34 debug: send_rsc_command: Skipping wait for 3
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=0, Pending=0, Fired=3, Skipped=0, Incomplete=4)
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op: add an operation operation start[4] on ocf::Dummy::prmDummyA for client 32295, its parameters: CRM_meta_id=[opDummyAStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=4)
lrmd[32292]: 2007/10/19_11:27:34 info: rsc:prmDummyA: start
crmd[32295]: 2007/10/19_11:27:34 debug: do_lrm_rsc_op: Recording pending op: 4 - prmDummyA_start_0 prmDummyA:4
Dummy[32316][32322]: 2007/10/19_11:27:34 INFO: xxxxx START xxxxx
Dummy[32316][32324]: 2007/10/19_11:27:34 DEBUG: prmDummyA start : 0
lrmd[32292]: 2007/10/19_11:27:34 info: Exiting prmDummyA:start process 32316 returned rc 0.
crmd[32295]: 2007/10/19_11:27:34 info: process_lrm_event: LRM operation prmDummyA_start_0 (call=4, rc=0) complete 
crmd[32295]: 2007/10/19_11:27:34 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_start_0 (0:0;5:1:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:27:34 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:27:34 debug: get_rsc_metadata: Retreiving metadata for Dummy::ocf:heartbeat
crmd[32295]: 2007/10/19_11:27:34 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[32295]: 2007/10/19_11:27:34 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[32295]: 2007/10/19_11:27:34 debug: do_update_resource: Sent resource state update message: 28
crmd[32295]: 2007/10/19_11:27:34 debug: process_lrm_event: Op prmDummyA_start_0 (call=4): Confirmed
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="11"/>
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:34 debug: cib_rsc_callback: Resource update 28 complete
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="12">
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.11 -> 0.2.12
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyA_start_0 (5) confirmed on prec370e (rc=0)
crmd[32295]: 2007/10/19_11:27:34 info: do_lrm_rsc_op: Performing op=prmDummyA_monitor_10000 key=6:1:32efb8b1-869d-45bf-a401-30b577f14ead)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 6: prmDummyA_monitor_10000 on prec370e
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op: add an operation operation monitor[5] on ocf::Dummy::prmDummyA for client 32295, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyAMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 7: prmDummyB_start_0 on prec370e
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=3, Pending=0, Fired=2, Skipped=0, Incomplete=2)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;5:1:32efb8b1-869d-45bf-a401-30b577f14ead" 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[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[32295]: 2007/10/19_11:27:34 debug: do_lrm_rsc_op: Recording pending op: 5 - prmDummyA_monitor_10000 prmDummyA:5
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.11 -> 0.2.12
crmd[32295]: 2007/10/19_11:27:34 info: do_lrm_rsc_op: Performing op=prmDummyB_start_0 key=7:1:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op: add an operation operation start[6] on ocf::Dummy::prmDummyB for client 32295, its parameters: CRM_meta_id=[opDummyBStart] CRM_meta_timeout=[60000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[start]  to the operation list.
lrmd[32292]: 2007/10/19_11:27:34 info: rsc:prmDummyB: start
crmd[32295]: 2007/10/19_11:27:34 debug: do_lrm_rsc_op: Recording pending op: 6 - prmDummyB_start_0 prmDummyB:6
Dummy[32333][32344]: 2007/10/19_11:27:34 INFO: xxxxx START xxxxx
Dummy[32332][32345]: 2007/10/19_11:27:34 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:27:34 info: Exiting prmDummyA:monitor process 32332 returned rc 0.
crmd[32295]: 2007/10/19_11:27:34 info: process_lrm_event: LRM operation prmDummyA_monitor_10000 (call=5, rc=0) complete 
Dummy[32333][32347]: 2007/10/19_11:27:34 DEBUG: prmDummyB start : 0
lrmd[32292]: 2007/10/19_11:27:34 info: Exiting prmDummyB:start process 32333 returned rc 0.
crmd[32295]: 2007/10/19_11:27:34 debug: do_update_resource: Sent resource state update message: 29
crmd[32295]: 2007/10/19_11:27:34 info: process_lrm_event: LRM operation prmDummyB_start_0 (call=6, rc=0) complete 
crmd[32295]: 2007/10/19_11:27:34 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_start_0 (0:0;7:1:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:27:34 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:27:34 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[32295]: 2007/10/19_11:27:34 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[32295]: 2007/10/19_11:27:34 debug: do_update_resource: Sent resource state update message: 30
crmd[32295]: 2007/10/19_11:27:34 debug: process_lrm_event: Op prmDummyB_start_0 (call=6): Confirmed
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="12"/>
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.12 -> 0.2.13
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="13">
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyA_monitor_10000 (6) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=4, Pending=1, Fired=0, Skipped=0, Incomplete=2)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;6:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="5" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.12 -> 0.2.13
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:34 debug: cib_rsc_callback: Resource update 29 complete
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.13 -> 0.2.14
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyB_start_0 (7) confirmed on prec370e (rc=0)
tengine[32299]: 2007/10/19_11:27:34 info: te_pseudo_action: Pseudo action 10 fired and confirmed
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="13"/>
tengine[32299]: 2007/10/19_11:27:34 info: send_rsc_command: Initiating action 8: prmDummyB_monitor_10000 on prec370e
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="14">
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=5, Pending=0, Fired=2, Skipped=0, Incomplete=0)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: Transition 1: (Complete=6, Pending=1, Fired=0, Skipped=0, Incomplete=0)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
crmd[32295]: 2007/10/19_11:27:34 debug: cib_rsc_callback: Resource update 30 complete
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;7:1:32efb8b1-869d-45bf-a401-30b577f14ead" 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[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
crmd[32295]: 2007/10/19_11:27:34 info: do_lrm_rsc_op: Performing op=prmDummyB_monitor_10000 key=8:1:32efb8b1-869d-45bf-a401-30b577f14ead)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.13 -> 0.2.14
lrmd[32292]: 2007/10/19_11:27:34 debug: on_msg_perform_op: add an operation operation monitor[7] on ocf::Dummy::prmDummyB for client 32295, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyBMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[monitor]  to the operation list.
crmd[32295]: 2007/10/19_11:27:34 debug: do_lrm_rsc_op: Recording pending op: 7 - prmDummyB_monitor_10000 prmDummyB:7
Dummy[32348][32354]: 2007/10/19_11:27:34 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:27:34 info: Exiting prmDummyB:monitor process 32348 returned rc 0.
crmd[32295]: 2007/10/19_11:27:34 info: process_lrm_event: LRM operation prmDummyB_monitor_10000 (call=7, rc=0) complete 
crmd[32295]: 2007/10/19_11:27:34 debug: do_update_resource: Sent resource state update message: 31
crmd[32295]: 2007/10/19_11:27:34 debug: cib_rsc_callback: Resource update 31 complete
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: - <cib num_updates="14"/>
mgmtd[32296]: 2007/10/19_11:27:34 debug: update cib finished
tengine[32299]: 2007/10/19_11:27:34 debug: te_update_diff: Processing diff (cib_update): 0.2.14 -> 0.2.15
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + <cib num_updates="15">
tengine[32299]: 2007/10/19_11:27:34 info: match_graph_event: Action prmDummyB_monitor_10000 (8) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:34 debug: run_graph: ====================================================
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:34 info: run_graph: Transition 1: (Complete=7, Pending=0, Fired=0, Skipped=0, Incomplete=0)
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:27:34 info: notify_crmd: Transition 1 status: te_complete - <null>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
cib[32291]: 2007/10/19_11:27:34 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;8:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="7" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:27:34 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:34 debug: send_peer_reply: Sending update diff 0.2.14 -> 0.2.15
crmd[32295]: 2007/10/19_11:27:34 debug: handle_request: Transition complete: te_complete/(null)
crmd[32295]: 2007/10/19_11:27:34 debug: register_fsa_input_adv: route_message appended FSA input 27 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32295]: 2007/10/19_11:27:34 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:27:34 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32295]: 2007/10/19_11:27:34 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: - <cib num_updates="15"/>
mgmtd[32296]: 2007/10/19_11:27:35 debug: update cib finished
crmd[32295]: 2007/10/19_11:27:35 debug: handle_request: Transition cancelled: te_abort/transient_attributes
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: + <cib num_updates="16">
tengine[32299]: 2007/10/19_11:27:35 debug: te_update_diff: Processing diff (cib_modify): 0.2.15 -> 0.2.16
crmd[32295]: 2007/10/19_11:27:35 debug: register_fsa_input_adv: route_message appended FSA input 28 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:27:35 info: extract_event: Aborting on transient_attributes changes for 6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6
crmd[32295]: 2007/10/19_11:27:35 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:35 info: update_abort_priority: Abort priority upgraded to 1000000
crmd[32295]: 2007/10/19_11:27:35 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +       <transient_attributes id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:35 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
crmd[32295]: 2007/10/19_11:27:35 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +         <instance_attributes id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +           <attributes>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +             <nvpair id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6-probe_complete" name="probe_complete" value="true"/>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause     <attributes>
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +           </attributes>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6-probe_complete" name="probe_complete" value="true"/>
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +         </instance_attributes>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause     </attributes>
crmd[32295]: 2007/10/19_11:27:35 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +       </transient_attributes>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +     </node_state>
tengine[32299]: 2007/10/19_11:27:35 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: +   </status>
tengine[32299]: 2007/10/19_11:27:35 debug: notify_crmd: Transition 1 status: te_abort - transient_attributes
cib[32291]: 2007/10/19_11:27:35 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:27:35 debug: send_peer_reply: Sending update diff 0.2.15 -> 0.2.16
crmd[32295]: 2007/10/19_11:27:35 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1192760855-18
pengine[32300]: 2007/10/19_11:27:35 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[32300]: 2007/10/19_11:27:35 debug: unpack_config: Default action timeout: 120s
pengine[32300]: 2007/10/19_11:27:35 debug: unpack_config: Default stickiness: 1000000
pengine[32300]: 2007/10/19_11:27:35 debug: unpack_config: Default failure stickiness: -1000000
pengine[32300]: 2007/10/19_11:27:35 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32300]: 2007/10/19_11:27:35 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32300]: 2007/10/19_11:27:35 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32300]: 2007/10/19_11:27:35 info: determine_online_status: Node prec370e is online
pengine[32300]: 2007/10/19_11:27:35 info: determine_online_status: Node prec370d is online
pengine[32300]: 2007/10/19_11:27:35 notice: group_print: Resource Group: grpDummy
pengine[32300]: 2007/10/19_11:27:35 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
crmd[32295]: 2007/10/19_11:27:35 debug: register_fsa_input_adv: route_message appended FSA input 29 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[32300]: 2007/10/19_11:27:35 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
crmd[32295]: 2007/10/19_11:27:35 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[32300]: 2007/10/19_11:27:35 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_LOG   
pengine[32300]: 2007/10/19_11:27:35 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
crmd[32295]: 2007/10/19_11:27:35 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
pengine[32300]: 2007/10/19_11:27:35 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[32300]: 2007/10/19_11:27:35 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 1000000
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: 200
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Assigning prec370e to prmDummyA
crmd[32295]: 2007/10/19_11:27:35 debug: do_te_invoke: Starting a transition
pengine[32300]: 2007/10/19_11:27:35 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[32300]: 2007/10/19_11:27:35 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[32300]: 2007/10/19_11:27:35 debug: native_assign_node: Assigning prec370e to prmDummyB
pengine[32300]: 2007/10/19_11:27:35 notice: NoRoleChange: Leave resource prmDummyA	(prec370e)
pengine[32300]: 2007/10/19_11:27:35 notice: NoRoleChange: Leave resource prmDummyB	(prec370e)
crmd[32295]: 2007/10/19_11:27:35 debug: handle_request: Transition complete: te_complete/(null)
tengine[32299]: 2007/10/19_11:27:35 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-2.bz2
crmd[32295]: 2007/10/19_11:27:35 debug: register_fsa_input_adv: route_message appended FSA input 30 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
tengine[32299]: 2007/10/19_11:27:35 info: unpack_graph: Unpacked transition 2: 0 actions in 0 synapses
crmd[32295]: 2007/10/19_11:27:35 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32299]: 2007/10/19_11:27:35 debug: print_graph: ## Empty transition graph ##
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_LOG   
tengine[32299]: 2007/10/19_11:27:35 debug: run_graph: ====================================================
crmd[32295]: 2007/10/19_11:27:35 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
tengine[32299]: 2007/10/19_11:27:35 info: run_graph: Transition 2: (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0)
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32299]: 2007/10/19_11:27:35 debug: print_graph: ## Empty transition graph ##
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32299]: 2007/10/19_11:27:35 info: notify_crmd: Transition 2 status: te_complete - <null>
crmd[32295]: 2007/10/19_11:27:35 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32299]: 2007/10/19_11:27:35 debug: print_graph: ## Empty transition graph ##
pengine[32300]: 2007/10/19_11:27:35 info: process_pe_message: Transition 2: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-2.bz2
cib[32291]: 2007/10/19_11:27:36 debug: log_data_element: cib:diff: - <cib num_updates="16"/>
mgmtd[32296]: 2007/10/19_11:27:36 debug: update cib finished
cib[32291]: 2007/10/19_11:27:36 debug: log_data_element: cib:diff: + <cib num_updates="17"/>
tengine[32299]: 2007/10/19_11:27:36 debug: te_update_diff: Processing diff (cib_modify): 0.2.16 -> 0.2.17
cib[32291]: 2007/10/19_11:27:36 debug: send_peer_reply: Sending update diff 0.2.16 -> 0.2.17
Dummy[32355][32361]: 2007/10/19_11:27:44 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:27:44 info: Exiting prmDummyA:monitor process 32355 returned rc 0.
Dummy[32362][32368]: 2007/10/19_11:27:44 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:27:44 info: Exiting prmDummyB:monitor process 32362 returned rc 0.
Dummy[32369][32375]: 2007/10/19_11:27:54 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:27:54 info: Exiting prmDummyA:monitor process 32369 returned rc 0.
Dummy[32376][32382]: 2007/10/19_11:27:54 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:27:54 info: Exiting prmDummyB:monitor process 32376 returned rc 0.
Dummy[32383][32389]: 2007/10/19_11:28:04 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:04 info: Exiting prmDummyA:monitor process 32383 returned rc 0.
Dummy[32390][32396]: 2007/10/19_11:28:04 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:04 info: Exiting prmDummyB:monitor process 32390 returned rc 0.
Dummy[32397][32403]: 2007/10/19_11:28:14 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:14 info: Exiting prmDummyA:monitor process 32397 returned rc 0.
Dummy[32404][32410]: 2007/10/19_11:28:14 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:14 info: Exiting prmDummyB:monitor process 32404 returned rc 0.
Dummy[32411][32417]: 2007/10/19_11:28:24 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:24 info: Exiting prmDummyA:monitor process 32411 returned rc 0.
Dummy[32418][32424]: 2007/10/19_11:28:24 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:24 info: Exiting prmDummyB:monitor process 32418 returned rc 0.
Dummy[32425][32431]: 2007/10/19_11:28:34 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:34 info: Exiting prmDummyA:monitor process 32425 returned rc 0.
Dummy[32432][32438]: 2007/10/19_11:28:34 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:34 info: Exiting prmDummyB:monitor process 32432 returned rc 0.
Dummy[32439][32445]: 2007/10/19_11:28:44 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:44 info: Exiting prmDummyA:monitor process 32439 returned rc 0.
Dummy[32446][32452]: 2007/10/19_11:28:44 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:44 info: Exiting prmDummyB:monitor process 32446 returned rc 0.
Dummy[32453][32459]: 2007/10/19_11:28:54 DEBUG: prmDummyA monitor : 0
lrmd[32292]: 2007/10/19_11:28:54 info: Exiting prmDummyA:monitor process 32453 returned rc 0.
Dummy[32460][32466]: 2007/10/19_11:28:54 DEBUG: prmDummyB monitor : 0
lrmd[32292]: 2007/10/19_11:28:54 info: Exiting prmDummyB:monitor process 32460 returned rc 0.
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: - <cib epoch="2" num_updates="17">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -   <configuration>
mgmtd[32296]: 2007/10/19_11:28:58 debug: update cib finished
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -     <resources>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -       <group id="grpDummy">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -         <primitive id="prmDummyA">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -           <operations>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyAStart" name="start" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyAMonitor" name="monitor" interval="10s" timeout="10s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyAStop" name="stop" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -           </operations>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -         </primitive>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -         <primitive id="prmDummyB">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -           <operations>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyBStart" name="start" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyBMonitor" name="monitor" interval="10s" timeout="10s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -             <op id="opDummyBStop" name="stop" timeout="60s" on_fail="restart"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -           </operations>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -         </primitive>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -       </group>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -     </resources>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: -   </configuration>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: - </cib>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: + <cib epoch="3" num_updates="1">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +   <configuration>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +     <resources>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +       <group id="grpDummy">
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +         <primitive id="prmDummyC" class="ocf" type="Dummy" provider="heartbeat"/>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +       </group>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +     </resources>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: +   </configuration>
cib[32291]: 2007/10/19_11:28:58 info: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:28:58 debug: send_peer_reply: Sending update diff 0.2.17 -> 0.3.1
cib[32468]: 2007/10/19_11:28:58 debug: write_cib_contents: Archiving current version
cib[32468]: 2007/10/19_11:28:58 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32468]: 2007/10/19_11:28:58 debug: archive_file: /var/lib/heartbeat/crm/cib.xml archived as /var/lib/heartbeat/crm/cib.xml.last
cib[32468]: 2007/10/19_11:28:58 debug: archive_file: /var/lib/heartbeat/crm/cib.xml.sig archived as /var/lib/heartbeat/crm/cib.xml.sig.last
cib[32468]: 2007/10/19_11:28:58 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32468]: 2007/10/19_11:28:58 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
cib[32468]: 2007/10/19_11:28:58 debug: write_cib_contents: Verified CIB archive
tengine[32299]: 2007/10/19_11:28:58 debug: te_update_diff: Processing diff (cib_replace): 0.2.17 -> 0.3.1
tengine[32299]: 2007/10/19_11:28:58 debug: need_abort: Aborting on change to epoch
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs <cib epoch="3" num_updates="1">
crmd[32295]: 2007/10/19_11:28:58 debug: handle_request: Transition cancelled: te_abort/Non-status change
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs   <configuration>
crmd[32295]: 2007/10/19_11:28:58 debug: register_fsa_input_adv: route_message appended FSA input 31 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs     <resources>
crmd[32295]: 2007/10/19_11:28:58 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs       <group id="grpDummy">
crmd[32295]: 2007/10/19_11:28:58 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs         <primitive id="prmDummyC" class="ocf" type="Dummy" provider="heartbeat"/>
crmd[32295]: 2007/10/19_11:28:58 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs       </group>
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs     </resources>
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs   </configuration>
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 debug: log_data_element: need_abort: Abort: CIB Attrs </cib>
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
tengine[32299]: 2007/10/19_11:28:58 info: update_abort_priority: Abort priority upgraded to 1000000
crmd[32295]: 2007/10/19_11:28:58 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
tengine[32299]: 2007/10/19_11:28:58 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
tengine[32299]: 2007/10/19_11:28:58 debug: notify_crmd: Transition 2 status: te_abort - Non-status change
tengine[32299]: 2007/10/19_11:28:58 debug: print_graph: ## Empty transition graph ##
cib[32468]: 2007/10/19_11:28:58 debug: write_cib_contents: Wrote CIB to disk
cib[32468]: 2007/10/19_11:28:58 info: write_cib_contents: Wrote version 0.3.1 of the CIB to disk (digest: 82e3d79563270346a3216747ff5edbbf)
crmd[32295]: 2007/10/19_11:28:58 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1192760938-20
pengine[32300]: 2007/10/19_11:28:58 debug: cluster_option: Using default value 'true' for cluster option 'start-failure-is-fatal'
pengine[32300]: 2007/10/19_11:28:58 debug: unpack_config: Default action timeout: 120s
pengine[32300]: 2007/10/19_11:28:58 debug: unpack_config: Default stickiness: 1000000
pengine[32300]: 2007/10/19_11:28:58 debug: unpack_config: Default failure stickiness: -1000000
pengine[32300]: 2007/10/19_11:28:58 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32300]: 2007/10/19_11:28:58 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32300]: 2007/10/19_11:28:58 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32300]: 2007/10/19_11:28:58 info: determine_online_status: Node prec370e is online
pengine[32300]: 2007/10/19_11:28:58 info: determine_online_status: Node prec370d is online
pengine[32300]: 2007/10/19_11:28:58 notice: group_print: Resource Group: grpDummy
pengine[32300]: 2007/10/19_11:28:58 notice: native_print:     prmDummyC	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:28:58 notice: native_print:     prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
pengine[32300]: 2007/10/19_11:28:58 notice: native_print:     prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[32300]: 2007/10/19_11:28:58 debug: group_rsc_location: Processing rsc_location rulNode1 for grpDummy
pengine[32300]: 2007/10/19_11:28:58 debug: group_rsc_location: Processing rsc_location rulNode2 for grpDummy
pengine[32300]: 2007/10/19_11:28:58 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy
pengine[32300]: 2007/10/19_11:28:58 info: check_action_definition: Orphan action will be stopped: prmDummyA_monitor_10000 on prec370e
pengine[32300]: 2007/10/19_11:28:58 info: check_action_definition: Orphan action will be stopped: prmDummyB_monitor_10000 on prec370e
pengine[32300]: 2007/10/19_11:28:58 debug: native_print: Allocating: prmDummyC	(heartbeat::ocf:Dummy):	Stopped 
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyC, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyC, Node[1] prec370d: 200
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Assigning prec370e to prmDummyC
pengine[32300]: 2007/10/19_11:28:58 debug: native_color: prmDummyA: Pre-Processing group:internal_colocation (prmDummyC)
pengine[32300]: 2007/10/19_11:28:58 debug: native_print: Allocating: prmDummyA	(heartbeat::ocf:Dummy):	Started prec370e
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyA, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyA, Node[1] prec370d: -1000000
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Assigning prec370e to prmDummyA
pengine[32300]: 2007/10/19_11:28:58 debug: native_color: prmDummyB: Pre-Processing group:internal_colocation (prmDummyA)
pengine[32300]: 2007/10/19_11:28:58 debug: native_print: Allocating: prmDummyB	(heartbeat::ocf:Dummy):	Started prec370e
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyB, Node[0] prec370e: 1000000
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Color prmDummyB, Node[1] prec370d: -1000000
pengine[32300]: 2007/10/19_11:28:58 debug: native_assign_node: Assigning prec370e to prmDummyB
pengine[32300]: 2007/10/19_11:28:58 notice: StartRsc:  prec370e	Start prmDummyC
pengine[32300]: 2007/10/19_11:28:58 notice: NoRoleChange: Leave resource prmDummyA	(prec370e)
pengine[32300]: 2007/10/19_11:28:58 notice: NoRoleChange: Leave resource prmDummyB	(prec370e)
pengine[32300]: 2007/10/19_11:28:58 debug: update_action:    * (implies right) Marking action prmDummyA_start_0 mandatory because of prmDummyC_start_0
pengine[32300]: 2007/10/19_11:28:58 debug: update_action:    * (implies right) Marking action prmDummyB_start_0 mandatory because of prmDummyA_start_0
cib[32468]: 2007/10/19_11:28:58 debug: write_cib_contents: Wrote digest to disk
cib[32468]: 2007/10/19_11:28:58 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/crm/cib.xml.sig)
cib[32468]: 2007/10/19_11:28:58 info: retrieveCib: Reading cluster configuration from: /var/lib/heartbeat/crm/cib.xml.last (digest: /var/lib/heartbeat/crm/cib.xml.sig.last)
crmd[32295]: 2007/10/19_11:28:58 debug: register_fsa_input_adv: route_message appended FSA input 32 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
cib[32468]: 2007/10/19_11:28:58 debug: write_cib_contents: Wrote and verified CIB
tengine[32299]: 2007/10/19_11:28:58 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-3.bz2
crmd[32295]: 2007/10/19_11:28:58 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32299]: 2007/10/19_11:28:58 info: unpack_graph: Unpacked transition 3: 12 actions in 12 synapses
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32295]: 2007/10/19_11:28:58 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 debug: initiate_action: Action 5: Increasing IDLE timer to 240000
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 info: send_rsc_command: Initiating action 5: prmDummyC_monitor_0 on prec370e
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32299]: 2007/10/19_11:28:58 debug: send_rsc_command: Action 5: Increasing transition 3 timeout to 360000 (2*120000 + 120000)
crmd[32295]: 2007/10/19_11:28:58 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[32299]: 2007/10/19_11:28:58 info: send_rsc_command: Initiating action 7: prmDummyC_monitor_0 on prec370d
crmd[32295]: 2007/10/19_11:28:58 debug: do_te_invoke: Starting a transition
tengine[32299]: 2007/10/19_11:28:58 info: send_rsc_command: Initiating action 9: prmDummyA_cancel_10000 on prec370e
tengine[32299]: 2007/10/19_11:28:58 info: send_rsc_command: Initiating action 10: prmDummyB_cancel_10000 on prec370e
tengine[32299]: 2007/10/19_11:28:58 debug: run_graph: Transition 3: (Complete=0, Pending=0, Fired=4, Skipped=0, Incomplete=8)
crmd[32295]: 2007/10/19_11:28:58 debug: get_lrm_resource: Adding rsc prmDummyC before operation
lrmd[32292]: 2007/10/19_11:28:58 debug: on_msg_add_rsc:client [32295] adds resource prmDummyC
crmd[32295]: 2007/10/19_11:28:58 info: do_lrm_rsc_op: Performing op=prmDummyC_monitor_0 key=5:3:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:28:58 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyC
lrmd[32292]: 2007/10/19_11:28:58 debug: on_msg_perform_op: add an operation operation monitor[8] on ocf::Dummy::prmDummyC for client 32295, its parameters: CRM_meta_op_target_rc=[7] CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[32292]: 2007/10/19_11:28:58 info: rsc:prmDummyC: monitor
lrmd[32292]: 2007/10/19_11:28:58 debug: cancel_op: operation monitor[5] on ocf::Dummy::prmDummyA for client 32295, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyAMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[monitor]  cancelled
crmd[32295]: 2007/10/19_11:28:58 debug: do_lrm_rsc_op: Recording pending op: 8 - prmDummyC_monitor_0 prmDummyC:8
pengine[32300]: 2007/10/19_11:28:58 info: process_pe_message: Transition 3: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-3.bz2
crmd[32295]: 2007/10/19_11:28:58 debug: cancel_op: Cancelling op 5 for prmDummyA (prmDummyA_monitor_10000)
crmd[32295]: 2007/10/19_11:28:58 info: send_direct_ack: ACK'ing resource op prmDummyA_monitor_10000 from 9:3:32efb8b1-869d-45bf-a401-30b577f14ead: lrm_invoke-lrmd-1192760938-22
tengine[32299]: 2007/10/19_11:28:58 info: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1192760938-22 from prec370e
tengine[32299]: 2007/10/19_11:28:58 info: match_graph_event: Action prmDummyA_monitor_10000 (9) confirmed on prec370e (rc=0)
tengine[32299]: 2007/10/19_11:28:58 debug: run_graph: Transition 3: (Complete=1, Pending=3, Fired=0, Skipped=0, Incomplete=8)
lrmd[32292]: 2007/10/19_11:28:58 debug: cancel_op: operation monitor[7] on ocf::Dummy::prmDummyB for client 32295, its parameters: CRM_meta_interval=[10000] CRM_meta_id=[opDummyBMonitor] CRM_meta_timeout=[10000] CRM_meta_on_fail=[restart] crm_feature_set=[2.0] CRM_meta_name=[monitor]  cancelled
crmd[32295]: 2007/10/19_11:28:58 debug: cancel_op: Cancelling op 7 for prmDummyB (prmDummyB_monitor_10000)
crmd[32295]: 2007/10/19_11:28:58 info: send_direct_ack: ACK'ing resource op prmDummyB_monitor_10000 from 10:3:32efb8b1-869d-45bf-a401-30b577f14ead: lrm_invoke-lrmd-1192760938-23
crmd[32295]: 2007/10/19_11:28:58 info: process_lrm_event: LRM operation prmDummyA_monitor_10000 (call=5, rc=-2) Cancelled 
crmd[32295]: 2007/10/19_11:28:58 debug: delete_op_entry: async: Sending delete op for prmDummyA_monitor_10000 (call=5)
crmd[32295]: 2007/10/19_11:28:58 debug: process_lrm_event: Op prmDummyA_monitor_10000 (call=5): Confirmed
crmd[32295]: 2007/10/19_11:28:58 info: process_lrm_event: LRM operation prmDummyB_monitor_10000 (call=7, rc=-2) Cancelled 
crmd[32295]: 2007/10/19_11:28:58 debug: delete_op_entry: async: Sending delete op for prmDummyB_monitor_10000 (call=7)
crmd[32295]: 2007/10/19_11:28:58 debug: process_lrm_event: Op prmDummyB_monitor_10000 (call=7): Confirmed
tengine[32299]: 2007/10/19_11:28:58 info: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1192760938-23 from prec370e
tengine[32299]: 2007/10/19_11:28:58 info: match_graph_event: Action prmDummyB_monitor_10000 (10) confirmed on prec370e (rc=0)
tengine[32299]: 2007/10/19_11:28:58 debug: run_graph: Transition 3: (Complete=2, Pending=2, Fired=0, Skipped=0, Incomplete=8)
mgmtd[32296]: 2007/10/19_11:28:58 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:58 debug: te_update_diff: Processing diff (cib_delete): 0.3.1 -> 0.3.2
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - <cib num_updates="1">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -   <status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -         <lrm_resources>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyA">
cib[32291]: 2007/10/19_11:28:58 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;6:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="5" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -           </lrm_resource>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -         </lrm_resources>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -       </lrm>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -     </node_state>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -   </status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - </cib>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: + <cib num_updates="2"/>
cib[32291]: 2007/10/19_11:28:58 debug: send_peer_reply: Sending update diff 0.3.1 -> 0.3.2
mgmtd[32296]: 2007/10/19_11:28:58 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:58 debug: te_update_diff: Processing diff (cib_delete): 0.3.2 -> 0.3.3
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - <cib num_updates="2">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -   <status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -         <lrm_resources>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyB">
cib[32291]: 2007/10/19_11:28:58 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;8:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="7" crm_feature_set="2.0" rc_code="0" op_status="0" interval="10000" op_digest="19240b0a103493c96459e91c1a816b50"/>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -           </lrm_resource>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -         </lrm_resources>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -       </lrm>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -     </node_state>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: -   </status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - </cib>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: + <cib num_updates="3"/>
cib[32291]: 2007/10/19_11:28:58 debug: send_peer_reply: Sending update diff 0.3.2 -> 0.3.3
Dummy[32469][32475]: 2007/10/19_11:28:58 DEBUG: prmDummyC monitor : 7
lrmd[32292]: 2007/10/19_11:28:58 WARN: Exiting prmDummyC:monitor process 32469 returned rc 7.
crmd[32295]: 2007/10/19_11:28:58 info: process_lrm_event: LRM operation prmDummyC_monitor_0 (call=8, rc=7) complete 
crmd[32295]: 2007/10/19_11:28:58 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyC_monitor_0 (0:7;5:3:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:28:58 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:28:58 debug: do_update_resource: Sent resource state update message: 36
crmd[32295]: 2007/10/19_11:28:58 debug: process_lrm_event: Op prmDummyC_monitor_0 (call=8): Confirmed
crmd[32295]: 2007/10/19_11:28:58 debug: cib_rsc_callback: Resource update 36 complete
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - <cib num_updates="3"/>
mgmtd[32296]: 2007/10/19_11:28:58 debug: update cib finished
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: + <cib num_updates="4">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +   <status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[32299]: 2007/10/19_11:28:58 debug: te_update_diff: Processing diff (cib_update): 0.3.3 -> 0.3.4
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC" type="Dummy" class="ocf" provider="heartbeat">
tengine[32299]: 2007/10/19_11:28:58 info: match_graph_event: Action prmDummyC_monitor_0 (5) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:28:58 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;5:3:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="8" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
tengine[32299]: 2007/10/19_11:28:58 info: send_rsc_command: Initiating action 4: probe_complete on prec370e
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +           </lrm_resource>
tengine[32299]: 2007/10/19_11:28:58 debug: send_rsc_command: Skipping wait for 4
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +         </lrm_resources>
tengine[32299]: 2007/10/19_11:28:58 debug: run_graph: Transition 3: (Complete=3, Pending=1, Fired=1, Skipped=0, Incomplete=7)
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +       </lrm>
tengine[32299]: 2007/10/19_11:28:58 debug: run_graph: Transition 3: (Complete=4, Pending=1, Fired=0, Skipped=0, Incomplete=7)
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:28:58 debug: send_peer_reply: Sending update diff 0.3.3 -> 0.3.4
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: - <cib num_updates="4"/>
mgmtd[32296]: 2007/10/19_11:28:58 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:58 debug: te_update_diff: Processing diff (cib_modify): 0.3.4 -> 0.3.5
cib[32291]: 2007/10/19_11:28:58 debug: log_data_element: cib:diff: + <cib num_updates="5"/>
cib[32291]: 2007/10/19_11:28:58 debug: send_peer_reply: Sending update diff 0.3.4 -> 0.3.5
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - <cib num_updates="5"/>
mgmtd[32296]: 2007/10/19_11:28:59 debug: update cib finished
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + <cib num_updates="6">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   <status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     <node_state id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       <lrm id="6a42b4b7-7a31-4ae7-b241-ed4ad4267ec6">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC" type="Dummy" class="ocf" provider="heartbeat">
tengine[32299]: 2007/10/19_11:28:59 debug: te_update_diff: Processing diff (cib_update): 0.3.5 -> 0.3.6
cib[32291]: 2007/10/19_11:28:59 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:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:7;7:3:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="4" crm_feature_set="2.0" rc_code="7" op_status="0" interval="0" op_digest="f2317cad3d54cec5d7d7aa7d0bf35cf8"/>
tengine[32299]: 2007/10/19_11:28:59 info: match_graph_event: Action prmDummyC_monitor_0 (7) confirmed on prec370d (rc=0)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           </lrm_resource>
tengine[32299]: 2007/10/19_11:28:59 info: send_rsc_command: Initiating action 6: probe_complete on prec370d
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         </lrm_resources>
tengine[32299]: 2007/10/19_11:28:59 debug: send_rsc_command: Skipping wait for 6
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       </lrm>
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=5, Pending=0, Fired=1, Skipped=0, Incomplete=6)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     </node_state>
tengine[32299]: 2007/10/19_11:28:59 info: te_pseudo_action: Pseudo action 3 fired and confirmed
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   </status>
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=6, Pending=0, Fired=1, Skipped=0, Incomplete=5)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + </cib>
tengine[32299]: 2007/10/19_11:28:59 info: te_pseudo_action: Pseudo action 16 fired and confirmed
cib[32291]: 2007/10/19_11:28:59 debug: send_peer_reply: Sending update diff 0.3.5 -> 0.3.6
tengine[32299]: 2007/10/19_11:28:59 info: send_rsc_command: Initiating action 11: prmDummyC_start_0 on prec370e
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=7, Pending=0, Fired=2, Skipped=0, Incomplete=3)
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=8, Pending=1, Fired=0, Skipped=0, Incomplete=3)
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyC
crmd[32295]: 2007/10/19_11:28:59 info: do_lrm_rsc_op: Performing op=prmDummyC_start_0 key=11:3:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op: add an operation operation start[9] on ocf::Dummy::prmDummyC for client 32295, its parameters: CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[32292]: 2007/10/19_11:28:59 info: rsc:prmDummyC: start
crmd[32295]: 2007/10/19_11:28:59 debug: do_lrm_rsc_op: Recording pending op: 9 - prmDummyC_start_0 prmDummyC:9
Dummy[32476][32482]: 2007/10/19_11:28:59 INFO: xxxxx START xxxxx
Dummy[32476][32484]: 2007/10/19_11:28:59 DEBUG: prmDummyC start : 0
lrmd[32292]: 2007/10/19_11:28:59 info: Exiting prmDummyC:start process 32476 returned rc 0.
crmd[32295]: 2007/10/19_11:28:59 info: process_lrm_event: LRM operation prmDummyC_start_0 (call=9, rc=0) complete 
crmd[32295]: 2007/10/19_11:28:59 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyC_start_0 (0:0;11:3:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:28:59 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:28:59 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[32295]: 2007/10/19_11:28:59 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[32295]: 2007/10/19_11:28:59 debug: do_update_resource: Sent resource state update message: 39
crmd[32295]: 2007/10/19_11:28:59 debug: process_lrm_event: Op prmDummyC_start_0 (call=9): Confirmed
crmd[32295]: 2007/10/19_11:28:59 debug: cib_rsc_callback: Resource update 39 complete
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - <cib num_updates="6"/>
mgmtd[32296]: 2007/10/19_11:28:59 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:59 debug: te_update_diff: Processing diff (cib_update): 0.3.6 -> 0.3.7
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + <cib num_updates="7">
tengine[32299]: 2007/10/19_11:28:59 info: match_graph_event: Action prmDummyC_start_0 (11) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   <status>
tengine[32299]: 2007/10/19_11:28:59 info: send_rsc_command: Initiating action 13: prmDummyA_start_0 on prec370e
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=9, Pending=0, Fired=1, Skipped=0, Incomplete=2)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyC">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummyC_start_0" operation="start" crm-debug-origin="do_update_resource" transition_key="11:3:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;11:3:32efb8b1-869d-45bf-a401-30b577f14ead" 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[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:28:59 debug: send_peer_reply: Sending update diff 0.3.6 -> 0.3.7
crmd[32295]: 2007/10/19_11:28:59 info: do_lrm_rsc_op: Performing op=prmDummyA_start_0 key=13:3:32efb8b1-869d-45bf-a401-30b577f14ead)
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyA
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op: add an operation operation start[10] on ocf::Dummy::prmDummyA for client 32295, its parameters: CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
lrmd[32292]: 2007/10/19_11:28:59 info: rsc:prmDummyA: start
crmd[32295]: 2007/10/19_11:28:59 debug: do_lrm_rsc_op: Recording pending op: 10 - prmDummyA_start_0 prmDummyA:10
Dummy[32485][32491]: 2007/10/19_11:28:59 INFO: xxxxx START xxxxx
Dummy[32485][32492]: 2007/10/19_11:28:59 DEBUG: prmDummyA start : 0
lrmd[32292]: 2007/10/19_11:28:59 info: Exiting prmDummyA:start process 32485 returned rc 0.
crmd[32295]: 2007/10/19_11:28:59 info: process_lrm_event: LRM operation prmDummyA_start_0 (call=10, rc=0) complete 
crmd[32295]: 2007/10/19_11:28:59 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyA_start_0 (0:0;13:3:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:28:59 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:28:59 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[32295]: 2007/10/19_11:28:59 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[32295]: 2007/10/19_11:28:59 debug: do_update_resource: Sent resource state update message: 40
crmd[32295]: 2007/10/19_11:28:59 debug: process_lrm_event: Op prmDummyA_start_0 (call=10): Confirmed
mgmtd[32296]: 2007/10/19_11:28:59 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:59 debug: te_update_diff: Processing diff (cib_update): 0.3.7 -> 0.3.8
tengine[32299]: 2007/10/19_11:28:59 info: match_graph_event: Action prmDummyA_start_0 (13) confirmed on prec370e (rc=0)
tengine[32299]: 2007/10/19_11:28:59 info: send_rsc_command: Initiating action 15: prmDummyB_start_0 on prec370e
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - <cib num_updates="7">
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=10, Pending=0, Fired=1, Skipped=0, Incomplete=1)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -   <status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -         <lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyA">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -             <lrm_rsc_op transition_key="5:1:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;5:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="4" id="prmDummyA_start_0"/>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -           </lrm_resource>
crmd[32295]: 2007/10/19_11:28:59 debug: cib_rsc_callback: Resource update 40 complete
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -         </lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -       </lrm>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -     </node_state>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -   </status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - </cib>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + <cib num_updates="8">
crmd[32295]: 2007/10/19_11:28:59 info: do_lrm_rsc_op: Performing op=prmDummyB_start_0 key=15:3:32efb8b1-869d-45bf-a401-30b577f14ead)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   <status>
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op:2278: copying parameters for rsc prmDummyB
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
lrmd[32292]: 2007/10/19_11:28:59 debug: on_msg_perform_op: add an operation operation start[11] on ocf::Dummy::prmDummyB for client 32295, its parameters: CRM_meta_timeout=[120000] crm_feature_set=[2.0]  to the operation list.
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
lrmd[32292]: 2007/10/19_11:28:59 info: rsc:prmDummyB: start
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyA">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +             <lrm_rsc_op transition_key="13:3:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;13:3:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="10" id="prmDummyA_start_0"/>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       </lrm>
crmd[32295]: 2007/10/19_11:28:59 debug: do_lrm_rsc_op: Recording pending op: 11 - prmDummyB_start_0 prmDummyB:11
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:28:59 debug: send_peer_reply: Sending update diff 0.3.7 -> 0.3.8
Dummy[32493][32499]: 2007/10/19_11:28:59 INFO: xxxxx START xxxxx
Dummy[32493][32500]: 2007/10/19_11:28:59 DEBUG: prmDummyB start : 0
lrmd[32292]: 2007/10/19_11:28:59 info: Exiting prmDummyB:start process 32493 returned rc 0.
crmd[32295]: 2007/10/19_11:28:59 info: process_lrm_event: LRM operation prmDummyB_start_0 (call=11, rc=0) complete 
crmd[32295]: 2007/10/19_11:28:59 debug: build_operation_update: Calculated digest f2317cad3d54cec5d7d7aa7d0bf35cf8 for prmDummyB_start_0 (0:0;15:3:32efb8b1-869d-45bf-a401-30b577f14ead)

crmd[32295]: 2007/10/19_11:28:59 debug: log_data_element: build_operation_update: digest:source <parameters/>
crmd[32295]: 2007/10/19_11:28:59 debug: get_rsc_restart_list: Attr state is not reloadable
crmd[32295]: 2007/10/19_11:28:59 debug: append_restart_list: f2317cad3d54cec5d7d7aa7d0bf35cf8 :  state 
crmd[32295]: 2007/10/19_11:28:59 debug: do_update_resource: Sent resource state update message: 41
crmd[32295]: 2007/10/19_11:28:59 debug: process_lrm_event: Op prmDummyB_start_0 (call=11): Confirmed
mgmtd[32296]: 2007/10/19_11:28:59 debug: update cib finished
tengine[32299]: 2007/10/19_11:28:59 debug: te_update_diff: Processing diff (cib_update): 0.3.8 -> 0.3.9
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - <cib num_updates="8">
tengine[32299]: 2007/10/19_11:28:59 info: match_graph_event: Action prmDummyB_start_0 (15) confirmed on prec370e (rc=0)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -   <status>
tengine[32299]: 2007/10/19_11:28:59 info: te_pseudo_action: Pseudo action 17 fired and confirmed
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: Transition 3: (Complete=11, Pending=0, Fired=1, Skipped=0, Incomplete=0)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
tengine[32299]: 2007/10/19_11:28:59 debug: run_graph: ====================================================
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -         <lrm_resources>
tengine[32299]: 2007/10/19_11:28:59 info: run_graph: Transition 3: (Complete=12, Pending=0, Fired=0, Skipped=0, Incomplete=0)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -           <lrm_resource id="prmDummyB">
tengine[32299]: 2007/10/19_11:28:59 info: notify_crmd: Transition 3 status: te_complete - <null>
crmd[32295]: 2007/10/19_11:28:59 debug: cib_rsc_callback: Resource update 41 complete
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -             <lrm_rsc_op transition_key="7:1:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;7:1:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="6" id="prmDummyB_start_0"/>
crmd[32295]: 2007/10/19_11:28:59 debug: handle_request: Transition complete: te_complete/(null)
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -           </lrm_resource>
crmd[32295]: 2007/10/19_11:28:59 debug: register_fsa_input_adv: route_message appended FSA input 33 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -         </lrm_resources>
crmd[32295]: 2007/10/19_11:28:59 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -       </lrm>
crmd[32295]: 2007/10/19_11:28:59 debug: do_fsa_action: actions:trace: 	// A_LOG   
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -     </node_state>
crmd[32295]: 2007/10/19_11:28:59 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: -   </status>
crmd[32295]: 2007/10/19_11:28:59 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: - </cib>
crmd[32295]: 2007/10/19_11:28:59 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + <cib num_updates="9">
crmd[32295]: 2007/10/19_11:28:59 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   <status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     <node_state id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       <lrm id="9d9ca527-cea9-470c-9e03-e49fe5630bba">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummyB">
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +             <lrm_rsc_op transition_key="15:3:32efb8b1-869d-45bf-a401-30b577f14ead" transition_magic="0:0;15:3:32efb8b1-869d-45bf-a401-30b577f14ead" call_id="11" id="prmDummyB_start_0"/>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +       </lrm>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +     </node_state>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: +   </status>
cib[32291]: 2007/10/19_11:28:59 debug: log_data_element: cib:diff: + </cib>
cib[32291]: 2007/10/19_11:28:59 debug: send_peer_reply: Sending update diff 0.3.8 -> 0.3.9
cib[32291]: 2007/10/19_11:29:01 debug: log_data_element: cib:diff: - <cib num_updates="9"/>
cib[32291]: 2007/10/19_11:29:01 debug: log_data_element: cib:diff: + <cib num_updates="10"/>
cib[32291]: 2007/10/19_11:29:01 debug: send_peer_reply: Sending update diff 0.3.9 -> 0.3.10
mgmtd[32296]: 2007/10/19_11:29:01 debug: update cib finished
tengine[32299]: 2007/10/19_11:29:01 debug: te_update_diff: Processing diff (cib_modify): 0.3.9 -> 0.3.10
cib[32291]: 2007/10/19_11:29:03 info: sync_our_cib: Syncing CIB to all peers
crmd[32295]: 2007/10/19_11:30:56 info: handle_request: Current ping state: S_IDLE
