logd[32676]: 2007/06/18_21:04:48 info: logd started with /etc/logd.cf.
logd[32677]: 2007/06/18_21:04:48 info: G_main_add_SignalHandler: Added signal handler for signal 15
logd[32676]: 2007/06/18_21:04:48 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32707]: 2007/06/18_21:04:48 info: Enabling logging daemon 
heartbeat[32707]: 2007/06/18_21:04:48 info: logfile and debug file are those specified in logd config file (default /etc/logd.cf)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(keepalive,2)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(deadtime,30)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(initdead,30)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(warntime,20)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(udpport,694)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(bcast,eth1)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(node,guest1)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(node,guest2)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(ping,172.16.157.1)
heartbeat[32707]: 2007/06/18_21:04:48 info: respawn directive: root /usr/lib/heartbeat/pingd -m 100 -d 5s -a default_ping_set
heartbeat[32707]: 2007/06/18_21:04:48 debug: uid=hacluster, gid=<null>
heartbeat[32707]: 2007/06/18_21:04:48 debug: uid=hacluster, gid=<null>
heartbeat[32707]: 2007/06/18_21:04:48 debug: uid=<null>, gid=haclient
heartbeat[32707]: 2007/06/18_21:04:48 debug: uid=root, gid=<null>
heartbeat[32707]: 2007/06/18_21:04:48 debug: uid=<null>, gid=haclient
heartbeat[32707]: 2007/06/18_21:04:48 debug: Beginning authentication parsing
heartbeat[32707]: 2007/06/18_21:04:48 debug: 16 max authentication methods
heartbeat[32707]: 2007/06/18_21:04:48 debug: Keyfile opened
heartbeat[32707]: 2007/06/18_21:04:48 debug: Keyfile perms OK
heartbeat[32707]: 2007/06/18_21:04:48 debug: 16 max authentication methods
heartbeat[32707]: 2007/06/18_21:04:48 debug: Found authentication method [md5]
heartbeat[32707]: 2007/06/18_21:04:48 info: AUTH: i=1: key = 0x96ce060, auth=0x2bf948, authname=md5
heartbeat[32707]: 2007/06/18_21:04:48 debug: Outbound signing method is 1
heartbeat[32707]: 2007/06/18_21:04:48 debug: Authentication parsing complete [1]
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(cluster,linux-ha)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(hopfudge,1)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(baud,19200)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(auto_failback,legacy)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(hbgenmethod,file)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(realtime,true)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(msgfmt,classic)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(conn_logd_time,60)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(log_badpack,true)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(coredumps,true)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(autojoin,none)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(uuidfrom,file)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(compression,zlib)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(compression_threshold,2)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(traditional_compression,no)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(max_rexmit_delay,250)
heartbeat[32707]: 2007/06/18_21:04:48 debug: Setting max_rexmit_delay to 250 ms
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(record_config_changes,on)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(record_pengine_inputs,on)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(enable_config_writes,on)
heartbeat[32707]: 2007/06/18_21:04:48 debug: add_option(memreserve,6500)
heartbeat[32707]: 2007/06/18_21:04:48 info: **************************
heartbeat[32707]: 2007/06/18_21:04:48 info: Configuration validated. Starting heartbeat 2.1.1
heartbeat[32707]: 2007/06/18_21:04:48 debug: HA configuration OK.  Heartbeat starting.
heartbeat[32708]: 2007/06/18_21:04:48 info: heartbeat: version 2.1.1
heartbeat[32708]: 2007/06/18_21:04:48 info: Heartbeat generation: 247
heartbeat[32708]: 2007/06/18_21:04:48 debug: uuid is:762a84bc-5633-4dcc-97ab-db3986cc778f
heartbeat[32708]: 2007/06/18_21:04:48 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[32708]: 2007/06/18_21:04:48 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[32708]: 2007/06/18_21:04:48 info: Removing /var/run/heartbeat/rsctmp failed, recreating.
heartbeat[32708]: 2007/06/18_21:04:48 debug: opening bcast eth1 (UDP/IP broadcast)
heartbeat[32708]: 2007/06/18_21:04:48 debug: opening ping 172.16.157.1 (ping membership)
heartbeat[32708]: 2007/06/18_21:04:48 debug: FIFO process pid: 32711
heartbeat[32708]: 2007/06/18_21:04:48 debug: glib: SO_BINDTODEVICE(r) set for device eth1
heartbeat[32708]: 2007/06/18_21:04:48 info: glib: UDP Broadcast heartbeat started on port 694 (694) interface eth1
heartbeat[32708]: 2007/06/18_21:04:48 debug: write process pid: 32712
heartbeat[32708]: 2007/06/18_21:04:48 debug: read child process pid: 32713
heartbeat[32708]: 2007/06/18_21:04:48 info: glib: UDP Broadcast heartbeat closed on port 694 interface eth1 - Status: 1
heartbeat[32708]: 2007/06/18_21:04:48 info: glib: ping heartbeat started.
heartbeat[32708]: 2007/06/18_21:04:48 debug: write process pid: 32714
heartbeat[32708]: 2007/06/18_21:04:48 debug: read child process pid: 32715
heartbeat[32708]: 2007/06/18_21:04:48 info: G_main_add_SignalHandler: Added signal handler for signal 17
heartbeat[32708]: 2007/06/18_21:04:48 debug: Limiting CPU: 42 CPU seconds every 60000 milliseconds
heartbeat[32708]: 2007/06/18_21:04:48 debug: pid 32708 locked in memory.
heartbeat[32708]: 2007/06/18_21:04:48 debug: Waiting for child processes to start
heartbeat[32708]: 2007/06/18_21:04:48 info: Local status now set to: 'up'
heartbeat[32708]: 2007/06/18_21:04:48 debug: All your child process are belong to us
heartbeat[32708]: 2007/06/18_21:04:48 debug: Starting local status message @ 2000 ms intervals
heartbeat[32711]: 2007/06/18_21:04:49 debug: pid 32711 locked in memory.
heartbeat[32711]: 2007/06/18_21:04:49 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[32714]: 2007/06/18_21:04:49 debug: pid 32714 locked in memory.
heartbeat[32714]: 2007/06/18_21:04:49 debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
heartbeat[32715]: 2007/06/18_21:04:49 debug: pid 32715 locked in memory.
heartbeat[32715]: 2007/06/18_21:04:49 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[32712]: 2007/06/18_21:04:49 debug: pid 32712 locked in memory.
heartbeat[32712]: 2007/06/18_21:04:49 debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
heartbeat[32713]: 2007/06/18_21:04:49 debug: pid 32713 locked in memory.
heartbeat[32713]: 2007/06/18_21:04:49 debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
heartbeat[32708]: 2007/06/18_21:04:50 info: Link guest1:eth1 up.
heartbeat[32708]: 2007/06/18_21:04:50 info: Link 172.16.157.1:172.16.157.1 up.
heartbeat[32708]: 2007/06/18_21:04:50 info: Status update for node 172.16.157.1: status ping
heartbeat[32708]: 2007/06/18_21:04:50 debug: Status seqno: 0 msgtime: 1182168288
heartbeat[32708]: 2007/06/18_21:04:50 debug: sending reqnodes msg to node guest1
heartbeat[32708]: 2007/06/18_21:04:50 info: Status update for node guest1: status up
heartbeat[32708]: 2007/06/18_21:04:50 debug: Status seqno: 2 msgtime: 1182168287
heartbeat[32708]: 2007/06/18_21:04:50 info: Link guest2:eth1 up.
heartbeat[32708]: 2007/06/18_21:04:50 debug: Get a reqnodes message from guest1
heartbeat[32708]: 2007/06/18_21:04:50 debug: get_delnodelist: delnodelist= 
heartbeat[32708]: 2007/06/18_21:04:50 debug: Get a repnodes msg from guest1
heartbeat[32708]: 2007/06/18_21:04:50 debug: nodelist received:guest1 guest2 
heartbeat[32708]: 2007/06/18_21:04:50 info: Comm_now_up(): updating status to active
heartbeat[32708]: 2007/06/18_21:04:50 info: Local status now set to: 'active'
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/ccm" (90,90)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/cib" (90,90)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/lrmd -r" (0,0)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/stonithd" (0,0)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/attrd" (90,90)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/crmd" (90,90)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/mgmtd -v" (0,0)
heartbeat[32708]: 2007/06/18_21:04:50 info: Starting child client "/usr/lib/heartbeat/pingd -m 100 -d 5s -a default_ping_set" (0,0)
heartbeat[32708]: 2007/06/18_21:04:50 WARN: G_CH_dispatch_int: Dispatch function for read child took too long to execute: 100 ms (> 50 ms) (GSource: 0x96d98e8)
heartbeat[32708]: 2007/06/18_21:04:50 info: Status update for node guest1: status active
heartbeat[32708]: 2007/06/18_21:04:50 debug: Status seqno: 7 msgtime: 1182168289
heartbeat[32719]: 2007/06/18_21:04:50 info: Starting "/usr/lib/heartbeat/ccm" as uid 90  gid 90 (pid 32719)
ccm[32719]: 2007/06/18_21:04:51 debug: Signing in with Heartbeat
heartbeat[32708]: 2007/06/18_21:04:51 debug: APIregistration_dispatch() {
heartbeat[32708]: 2007/06/18_21:04:51 debug: process_registerevent() {
heartbeat[32708]: 2007/06/18_21:04:51 debug: client->gsource = 0x96e2650
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*process_registerevent*/;
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*APIregistration_dispatch*/;
heartbeat[32708]: 2007/06/18_21:04:51 debug: Checking client authorization for client ccm (90:90)
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest1
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest2
heartbeat[32708]: 2007/06/18_21:04:51 debug: Signing on API client 32719 (ccm)
heartbeat[32720]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/cib" as uid 90  gid 90 (pid 32720)
heartbeat[32721]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/lrmd -r" as uid 0  gid 0 (pid 32721)
lrmd[32721]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32722]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/stonithd" as uid 0  gid 0 (pid 32722)
heartbeat[32723]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/attrd" as uid 90  gid 90 (pid 32723)
heartbeat[32724]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/crmd" as uid 90  gid 90 (pid 32724)
heartbeat[32725]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/mgmtd -v" as uid 0  gid 0 (pid 32725)
heartbeat[32726]: 2007/06/18_21:04:51 info: Starting "/usr/lib/heartbeat/pingd -m 100 -d 5s -a default_ping_set" as uid 0  gid 0 (pid 32726)
lrmd[32721]: 2007/06/18_21:04:51 debug: LRM debug level set to 1
lrmd[32721]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 17
lrmd[32721]: 2007/06/18_21:04:51 debug: Enabling coredumps
lrmd[32721]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 10
lrmd[32721]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 12
lrmd[32721]: 2007/06/18_21:04:51 debug: main: run the loop...
lrmd[32721]: 2007/06/18_21:04:51 info: Started.
stonithd[32722]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 10
stonithd[32722]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 12
stonithd[32722]: 2007/06/18_21:04:51 debug: pid 32722 locked in memory.
heartbeat[32708]: 2007/06/18_21:04:51 debug: APIregistration_dispatch() {
heartbeat[32708]: 2007/06/18_21:04:51 debug: process_registerevent() {
ccm[32719]: 2007/06/18_21:04:51 info: Hostname: guest2
heartbeat[32708]: 2007/06/18_21:04:51 debug: client->gsource = 0x96e5c20
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*process_registerevent*/;
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*APIregistration_dispatch*/;
heartbeat[32708]: 2007/06/18_21:04:51 debug: Checking client authorization for client stonithd (0:0)
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest1
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest2
heartbeat[32708]: 2007/06/18_21:04:51 debug: Signing on API client 32722 (stonithd)
stonithd[32722]: 2007/06/18_21:04:51 info: Signing in with heartbeat.
stonithd[32722]: 2007/06/18_21:04:51 debug: Setting message filter mode
mgmtd[32725]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 15
mgmtd[32725]: 2007/06/18_21:04:51 debug: Enabling coredumps
mgmtd[32725]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 10
mgmtd[32725]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 12
heartbeat[32708]: 2007/06/18_21:04:51 debug: APIregistration_dispatch() {
heartbeat[32708]: 2007/06/18_21:04:51 debug: process_registerevent() {
heartbeat[32708]: 2007/06/18_21:04:51 debug: client->gsource = 0x96e6230
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*process_registerevent*/;
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*APIregistration_dispatch*/;
stonithd[32722]: 2007/06/18_21:04:51 debug: apichan=0x87c2300
stonithd[32722]: 2007/06/18_21:04:51 debug: callback_chan=0x87c1f10
stonithd[32722]: 2007/06/18_21:04:51 notice: /usr/lib/heartbeat/stonithd start up successfully.
stonithd[32722]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 17
heartbeat[32708]: 2007/06/18_21:04:51 debug: Checking client authorization for client mgmtd (0:0)
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest1
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest2
heartbeat[32708]: 2007/06/18_21:04:51 debug: Signing on API client 32725 (mgmtd)
lrmd[32721]: 2007/06/18_21:04:51 debug: on_msg_register:client mgmtd [32725] registered
mgmtd[32725]: 2007/06/18_21:04:51 info: init_crm
mgmtd[32725]: 2007/06/18_21:04:51 info: login to cib: 0, ret:-10
cib[32720]: 2007/06/18_21:04:51 debug: crm_set_env_options: HA_conn_logd_time = 60
cib[32720]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 15
cib[32720]: 2007/06/18_21:04:51 info: G_main_add_TriggerHandler: Added signal manual handler
cib[32720]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 17
cib[32720]: 2007/06/18_21:04:51 info: main: Retrieval of a per-action CIB: disabled
cib[32720]: 2007/06/18_21:04:51 WARN: readCibXmlFile: Cluster configuration not found: /var/lib/heartbeat/crm/cib.xml.  Creating an empty one.
cib[32720]: 2007/06/18_21:04:51 WARN: readCibXmlFile: No value for admin_epoch was specified in the configuration.
cib[32720]: 2007/06/18_21:04:51 WARN: readCibXmlFile: The reccomended course of action is to shutdown, run crm_verify and fix any errors it reports.
cib[32720]: 2007/06/18_21:04:51 WARN: readCibXmlFile: We will default to zero and continue but may get confused about which configuration to use if multiple nodes are powered up at the same time.
cib[32720]: 2007/06/18_21:04:51 debug: update_quorum: CCM quorum: old=(null), new=false
cib[32720]: 2007/06/18_21:04:51 debug: update_counters: Counters updated by readCibXmlFile
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk] <cib generated="true" admin_epoch="0" epoch="0" num_updates="0" have_quorum="false">
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]   <configuration>
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]     <crm_config/>
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]     <nodes/>
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]     <resources/>
heartbeat[32708]: 2007/06/18_21:04:51 debug: APIregistration_dispatch() {
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]     <constraints/>
attrd[32723]: 2007/06/18_21:04:51 debug: crm_set_env_options: HA_conn_logd_time = 60
heartbeat[32708]: 2007/06/18_21:04:51 debug: process_registerevent() {
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]   </configuration>
attrd[32723]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32708]: 2007/06/18_21:04:51 debug: client->gsource = 0x96e6b08
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk]   <status/>
attrd[32723]: 2007/06/18_21:04:51 debug: register_with_ha: Signing in with Heartbeat
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*process_registerevent*/;
cib[32720]: 2007/06/18_21:04:51 info: log_data_element: readCibXmlFile: [on-disk] </cib>
attrd[32723]: 2007/06/18_21:04:51 info: register_with_ha: Hostname: guest2
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*APIregistration_dispatch*/;
cib[32720]: 2007/06/18_21:04:51 notice: readCibXmlFile: Enabling DTD validation on the existing (sane) configuration
attrd[32723]: 2007/06/18_21:04:51 info: register_with_ha: UUID: 762a84bc-5633-4dcc-97ab-db3986cc778f
heartbeat[32708]: 2007/06/18_21:04:51 debug: Checking client authorization for client attrd (90:90)
cib[32720]: 2007/06/18_21:04:51 info: startCib: CIB Initialization completed successfully
attrd[32723]: 2007/06/18_21:04:51 debug: main: CIB signon attempt 0
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest1
cib[32720]: 2007/06/18_21:04:51 info: cib_register_ha: Signing in with Heartbeat
attrd[32723]: 2007/06/18_21:04:51 debug: init_client_ipc_comms_nodispatch: Could not init comms on: /var/run/heartbeat/crm/cib_rw
crmd[32724]: 2007/06/18_21:04:51 debug: crm_set_env_options: HA_conn_logd_time = 60
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest2
cib[32720]: 2007/06/18_21:04:51 info: cib_register_ha: FSA Hostname: guest2
attrd[32723]: 2007/06/18_21:04:51 debug: cib_native_signon: Connection to command channel failed
crmd[32724]: 2007/06/18_21:04:51 info: main: CRM Hg Version: Unknown

heartbeat[32708]: 2007/06/18_21:04:51 debug: Signing on API client 32723 (attrd)
cib[32720]: 2007/06/18_21:04:51 WARN: cib_init: CCM Activation failed
attrd[32723]: 2007/06/18_21:04:51 debug: cib_native_signon: Connection to CIB failed: connection failed
crmd[32724]: 2007/06/18_21:04:51 info: crmd_init: Starting crmd
heartbeat[32708]: 2007/06/18_21:04:51 debug: APIregistration_dispatch() {
cib[32720]: 2007/06/18_21:04:51 WARN: cib_init: CCM Connection failed 1 times (30 max)
attrd[32723]: 2007/06/18_21:04:51 debug: cib_native_signoff: Signing out of the CIB Service
crmd[32724]: 2007/06/18_21:04:51 debug: register_fsa_input_adv: crmd_init appended FSA input 1 (I_STARTUP) (cause=C_STARTUP) without data
heartbeat[32708]: 2007/06/18_21:04:51 debug: process_registerevent() {
crmd[32724]: 2007/06/18_21:04:51 debug: s_crmd_fsa: Processing I_STARTUP: [ state=S_STARTING cause=C_STARTUP origin=crmd_init ]
heartbeat[32708]: 2007/06/18_21:04:51 debug: client->gsource = 0x96eba58
crmd[32724]: 2007/06/18_21:04:51 debug: do_fsa_action: actions:trace: 	// A_LOG   
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*process_registerevent*/;
crmd[32724]: 2007/06/18_21:04:51 debug: do_fsa_action: actions:trace: 	// A_STARTUP
heartbeat[32708]: 2007/06/18_21:04:51 debug: }/*APIregistration_dispatch*/;
crmd[32724]: 2007/06/18_21:04:51 debug: do_startup: Registering Signal Handlers
heartbeat[32708]: 2007/06/18_21:04:51 debug: Checking client authorization for client cib (90:90)
crmd[32724]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 15
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest1
crmd[32724]: 2007/06/18_21:04:51 info: G_main_add_TriggerHandler: Added signal manual handler
heartbeat[32708]: 2007/06/18_21:04:51 debug: create_seq_snapshot_table:no missing packets found for node guest2
crmd[32724]: 2007/06/18_21:04:51 debug: do_startup: Creating CIB and LRM objects
heartbeat[32708]: 2007/06/18_21:04:51 debug: Signing on API client 32720 (cib)
crmd[32724]: 2007/06/18_21:04:51 debug: do_startup: Init server comms
crmd[32724]: 2007/06/18_21:04:51 info: G_main_add_SignalHandler: Added signal handler for signal 17
crmd[32724]: 2007/06/18_21:04:51 debug: do_fsa_action: actions:trace: 	// A_CIB_START
pingd[32726]: 2007/06/18_21:04:51 debug: crm_set_env_options: HA_conn_logd_time = 60
pingd[32726]: 2007/06/18_21:04:51 debug: main: attrd registration attempt: 0
cib[32720]: 2007/06/18_21:04:52 WARN: cib_init: CCM Activation failed
cib[32720]: 2007/06/18_21:04:52 WARN: cib_init: CCM Connection failed 2 times (30 max)
cib[32720]: 2007/06/18_21:04:53 WARN: cib_init: CCM Activation failed
cib[32720]: 2007/06/18_21:04:53 WARN: cib_init: CCM Connection failed 3 times (30 max)
heartbeat[32708]: 2007/06/18_21:04:53 WARN: 1 lost packet(s) for [guest1] [14:16]
heartbeat[32708]: 2007/06/18_21:04:53 info: No pkts missing from guest1!
ccm[32719]: 2007/06/18_21:04:53 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[32719]: 2007/06/18_21:04:53 debug: node state CCM_STATE_NONE -> CCM_STATE_NONE
ccm[32719]: 2007/06/18_21:04:53 info: G_main_add_SignalHandler: Added signal handler for signal 15
ccm[32719]: 2007/06/18_21:04:54 debug: recv msg hbapi-clstat from guest2, status:join
cib[32720]: 2007/06/18_21:04:54 info: cib_init: Starting cib mainloop
crmd[32724]: 2007/06/18_21:04:54 debug: cib_native_signon: Connection to CIB successful
crmd[32724]: 2007/06/18_21:04:54 info: do_cib_control: CIB connection established
crmd[32724]: 2007/06/18_21:04:54 debug: do_fsa_action: actions:trace: 	// A_HA_CONNECT
crmd[32724]: 2007/06/18_21:04:54 debug: register_with_ha: Signing in with Heartbeat
cib[32720]: 2007/06/18_21:04:54 info: cib_null_callback: Setting cib_refresh_notify callbacks for crmd: on
cib[32720]: 2007/06/18_21:04:54 info: cib_null_callback: Setting cib_diff_notify callbacks for mgmtd: on
heartbeat[32708]: 2007/06/18_21:04:54 WARN: 1 lost packet(s) for [guest1] [18:20]
heartbeat[32708]: 2007/06/18_21:04:54 info: No pkts missing from guest1!
heartbeat[32708]: 2007/06/18_21:04:54 debug: APIregistration_dispatch() {
heartbeat[32708]: 2007/06/18_21:04:54 debug: process_registerevent() {
heartbeat[32708]: 2007/06/18_21:04:54 debug: client->gsource = 0x96f6968
heartbeat[32708]: 2007/06/18_21:04:54 debug: }/*process_registerevent*/;
heartbeat[32708]: 2007/06/18_21:04:54 debug: }/*APIregistration_dispatch*/;
heartbeat[32708]: 2007/06/18_21:04:54 debug: Checking client authorization for client crmd (90:90)
cib[32720]: 2007/06/18_21:04:54 info: cib_client_status_callback: Status update: Client guest2/cib now has status [join]
crmd[32724]: 2007/06/18_21:04:54 info: register_with_ha: Hostname: guest2
heartbeat[32708]: 2007/06/18_21:04:54 debug: create_seq_snapshot_table:no missing packets found for node guest1
cib[32720]: 2007/06/18_21:04:54 debug: set_connected_peers: We now have 1 active peers
heartbeat[32708]: 2007/06/18_21:04:54 debug: create_seq_snapshot_table:no missing packets found for node guest2
cib[32720]: 2007/06/18_21:04:54 info: cib_client_status_callback: Status update: Client guest2/cib now has status [online]
heartbeat[32708]: 2007/06/18_21:04:54 debug: Signing on API client 32724 (crmd)
cib[32727]: 2007/06/18_21:04:54 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: da43bd0d89df52de3d7731d68840fc12)
crmd[32724]: 2007/06/18_21:04:54 info: register_with_ha: UUID: 762a84bc-5633-4dcc-97ab-db3986cc778f
crmd[32724]: 2007/06/18_21:04:55 info: populate_cib_nodes: Requesting the list of configured nodes
ccm[32719]: 2007/06/18_21:04:55 debug: send msg CCM_TYPE_PROTOVERSION to cluster, status:(null)
ccm[32719]: 2007/06/18_21:04:55 debug: node state CCM_STATE_NONE -> CCM_STATE_VERSION_REQUEST
cib[32720]: 2007/06/18_21:04:55 info: cib_client_status_callback: Status update: Client guest1/cib now has status [online]
cib[32720]: 2007/06/18_21:04:55 debug: set_connected_peers: We now have 2 active peers
ccm[32719]: 2007/06/18_21:04:55 debug: recv msg CCM_TYPE_PROTOVERSION from guest2, status:[null ptr]
mgmtd[32725]: 2007/06/18_21:04:55 debug: main: run the loop...
mgmtd[32725]: 2007/06/18_21:04:55 info: Started.
crmd[32724]: 2007/06/18_21:04:56 debug: populate_cib_nodes: Node 172.16.157.1: skipping 'ping'
attrd[32723]: 2007/06/18_21:04:56 debug: main: CIB signon attempt 1
attrd[32723]: 2007/06/18_21:04:56 debug: cib_native_signon: Connection to CIB successful
pingd[32726]: 2007/06/18_21:04:56 debug: init_client_ipc_comms_nodispatch: Could not init comms on: /var/run/heartbeat/crm/attrd
pingd[32726]: 2007/06/18_21:04:56 debug: main: attrd registration attempt: 1
crmd[32724]: 2007/06/18_21:04:56 notice: populate_cib_nodes: Node: guest2 (uuid: 762a84bc-5633-4dcc-97ab-db3986cc778f)
ccm[32719]: 2007/06/18_21:04:56 debug: recv msg CCM_TYPE_PROTOVERSION from guest1, status:[null ptr]
ccm[32719]: 2007/06/18_21:04:56 debug: No quorum selected,using default quorum plugin(majority:twonodes)
ccm[32719]: 2007/06/18_21:04:56 debug: quorum plugin: majority
ccm[32719]: 2007/06/18_21:04:56 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
ccm[32719]: 2007/06/18_21:04:56 debug: total_node_count=2, total_quorum_votes=200
ccm[32719]: 2007/06/18_21:04:56 debug: quorum plugin: twonodes
ccm[32719]: 2007/06/18_21:04:56 debug: cluster:linux-ha, member_count=1, member_quorum_votes=100
ccm[32719]: 2007/06/18_21:04:56 debug: total_node_count=2, total_quorum_votes=200
ccm[32719]: 2007/06/18_21:04:56 info: Break tie for 2 nodes cluster
ccm[32719]: 2007/06/18_21:04:56 debug: node state CCM_STATE_VERSION_REQUEST -> CCM_STATE_JOINED
ccm[32719]: 2007/06/18_21:04:56 debug: dump current membership 0xb7f62018
ccm[32719]: 2007/06/18_21:04:56 debug: 	leader=guest2
ccm[32719]: 2007/06/18_21:04:56 debug: 	transition=1
ccm[32719]: 2007/06/18_21:04:56 debug: 	status=CCM_STATE_JOINED
ccm[32719]: 2007/06/18_21:04:56 debug: 	has_quorum=1
ccm[32719]: 2007/06/18_21:04:56 debug: 	nodename=guest2 bornon=1
ccm[32719]: 2007/06/18_21:04:56 debug: quorum is 1
ccm[32719]: 2007/06/18_21:04:56 debug: delivering new membership to 1 clients: 
ccm[32719]: 2007/06/18_21:04:56 debug: client: pid =32720
ccm[32719]: 2007/06/18_21:04:56 debug: send msg CCM_TYPE_PROTOVERSION_RESP to guest1, status:(null)
cib[32720]: 2007/06/18_21:04:56 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
cib[32720]: 2007/06/18_21:04:56 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
cib[32720]: 2007/06/18_21:04:56 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=1)
cib[32720]: 2007/06/18_21:04:56 debug: set_transition: CCM transition: old=(null), new=1
cib[32720]: 2007/06/18_21:04:56 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
cib[32720]: 2007/06/18_21:04:56 info: cib_ccm_msg_callback: PEER: guest2
crmd[32724]: 2007/06/18_21:04:56 notice: populate_cib_nodes: Node: guest1 (uuid: a2db98b0-fa70-4eff-990a-0f1ee9bc1430)
crmd[32724]: 2007/06/18_21:04:56 info: do_ha_control: Connected to Heartbeat
crmd[32724]: 2007/06/18_21:04:56 debug: do_fsa_action: actions:trace: 	// A_READCONFIG
crmd[32724]: 2007/06/18_21:04:56 debug: do_fsa_action: actions:trace: 	// A_LRM_CONNECT
crmd[32724]: 2007/06/18_21:04:56 debug: do_lrm_control: Connecting to the LRM
lrmd[32721]: 2007/06/18_21:04:56 debug: on_msg_register:client crmd [32724] registered
mgmtd[32725]: 2007/06/18_21:04:56 debug: update cib finished
crmd[32724]: 2007/06/18_21:04:56 debug: do_lrm_control: LRM connection established
crmd[32724]: 2007/06/18_21:04:56 debug: do_fsa_action: actions:trace: 	// A_CCM_CONNECT
crmd[32724]: 2007/06/18_21:04:56 info: do_ccm_control: CCM connection established... waiting for first callback
crmd[32724]: 2007/06/18_21:04:56 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[32724]: 2007/06/18_21:04:56 info: do_started: Delaying start, CCM (0000000000100000) not connected
crmd[32724]: 2007/06/18_21:04:56 debug: register_fsa_input_adv: do_started prepended FSA input 2 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:04:56 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
crmd[32724]: 2007/06/18_21:04:56 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
crmd[32724]: 2007/06/18_21:04:56 debug: fsa_dump_inputs: Added input: 0000000000000100 (R_CIB_CONNECTED)
crmd[32724]: 2007/06/18_21:04:56 debug: fsa_dump_inputs: Added input: 0000000000000800 (R_LRM_CONNECTED)
crmd[32724]: 2007/06/18_21:04:56 info: crmd_init: Starting crmd's mainloop
crmd[32724]: 2007/06/18_21:04:56 debug: config_query_callback: Call 4 : Parsing CIB options
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '10s' for cluster option 'dc_deadtime'
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '0' for cluster option 'cluster_recheck_interval'
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '2min' for cluster option 'election_timeout'
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '20min' for cluster option 'shutdown_escalation'
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '3min' for cluster option 'crmd-integration-timeout'
crmd[32724]: 2007/06/18_21:04:56 notice: cluster_option: Using default value '10min' for cluster option 'crmd-finalization-timeout'
crmd[32724]: 2007/06/18_21:04:56 notice: crmd_client_status_callback: Status update: Client guest2/crmd now has status [online]
crmd[32724]: 2007/06/18_21:04:57 notice: crmd_client_status_callback: Status update: Client guest2/crmd now has status [online]
mgmtd[32725]: 2007/06/18_21:04:57 debug: update cib finished
cib[32728]: 2007/06/18_21:04:57 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: 163a47221d2e9036b4ee0455948e7f15)
cib[32729]: 2007/06/18_21:04:57 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: b96e8de595888218105e58dc25e17d84)
ccm[32719]: 2007/06/18_21:04:57 debug: recv msg CCM_TYPE_ALIVE from guest1, status:[null ptr]
ccm[32719]: 2007/06/18_21:04:57 debug: quorum plugin: majority
ccm[32719]: 2007/06/18_21:04:57 debug: cluster:linux-ha, member_count=2, member_quorum_votes=200
ccm[32719]: 2007/06/18_21:04:57 debug: total_node_count=2, total_quorum_votes=200
crmd[32724]: 2007/06/18_21:04:57 notice: crmd_client_status_callback: Status update: Client guest1/crmd now has status [online]
ccm[32719]: 2007/06/18_21:04:57 debug: send msg CCM_TYPE_MEM_LIST to cluster, status:(null)
ccm[32719]: 2007/06/18_21:04:57 debug: dump current membership 0xb7f62018
ccm[32719]: 2007/06/18_21:04:57 debug: 	leader=guest2
ccm[32719]: 2007/06/18_21:04:57 debug: 	transition=2
cib[32720]: 2007/06/18_21:04:57 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
ccm[32719]: 2007/06/18_21:04:57 debug: 	status=CCM_STATE_JOINED
cib[32720]: 2007/06/18_21:04:57 info: mem_handle_event: no mbr_track info
ccm[32719]: 2007/06/18_21:04:57 debug: 	has_quorum=1
cib[32720]: 2007/06/18_21:04:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[32719]: 2007/06/18_21:04:57 debug: 	nodename=guest2 bornon=1
cib[32720]: 2007/06/18_21:04:57 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
ccm[32719]: 2007/06/18_21:04:57 debug: 	nodename=guest1 bornon=2
cib[32720]: 2007/06/18_21:04:57 debug: cib_ccm_msg_callback: Process CCM event=NEW MEMBERSHIP (id=2)
ccm[32719]: 2007/06/18_21:04:57 debug: quorum is 1
cib[32720]: 2007/06/18_21:04:57 debug: set_transition: CCM transition: old=1, new=2
ccm[32719]: 2007/06/18_21:04:57 debug: delivering new membership to 2 clients: 
cib[32720]: 2007/06/18_21:04:57 debug: cib_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
ccm[32719]: 2007/06/18_21:04:57 debug: client: pid =32720
cib[32720]: 2007/06/18_21:04:57 info: cib_ccm_msg_callback: PEER: guest2
ccm[32719]: 2007/06/18_21:04:57 debug: client: pid =32724
cib[32720]: 2007/06/18_21:04:57 info: cib_ccm_msg_callback: PEER: guest1
cib[32730]: 2007/06/18_21:04:57 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: 9725138e8d041c84abefa31d9efc82ce)
ccm[32719]: 2007/06/18_21:04:57 debug: recv msg CCM_TYPE_MEM_LIST from guest2, status:[null ptr]
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_STARTED
ccm[32719]: 2007/06/18_21:04:57 WARN: ccm_state_joined: received message with unknown cookie, just dropping
crmd[32724]: 2007/06/18_21:04:57 info: do_started: Delaying start, CCM (0000000000100000) not connected
ccm[32719]: 2007/06/18_21:04:57 debug: dump current membership 0xb7f62018
crmd[32724]: 2007/06/18_21:04:57 debug: register_fsa_input_adv: do_started prepended FSA input 3 (I_WAIT_FOR_EVENT) (cause=C_FSA_INTERNAL) without data
ccm[32719]: 2007/06/18_21:04:57 debug: 	leader=guest2
crmd[32724]: 2007/06/18_21:04:57 debug: register_fsa_input_adv: Stalling the FSA pending further input: cause=C_FSA_INTERNAL
ccm[32719]: 2007/06/18_21:04:57 debug: 	transition=2
crmd[32724]: 2007/06/18_21:04:57 debug: s_crmd_fsa: Exiting the FSA: queue=0, fsa_actions=0x2, stalled=true
ccm[32719]: 2007/06/18_21:04:57 debug: 	status=CCM_STATE_JOINED
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
ccm[32719]: 2007/06/18_21:04:57 debug: 	has_quorum=1
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: instance=1, nodes=1, new=1, lost=0, n_idx=0, new_idx=0, old_idx=3
ccm[32719]: 2007/06/18_21:04:57 debug: 	nodename=guest2 bornon=1
crmd[32724]: 2007/06/18_21:04:57 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=1)
ccm[32719]: 2007/06/18_21:04:57 debug: 	nodename=guest1 bornon=2
crmd[32724]: 2007/06/18_21:04:57 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 4 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: Got an event OC_EV_MS_INVALID from ccm
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: no mbr_track info
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm
crmd[32724]: 2007/06/18_21:04:57 info: mem_handle_event: instance=2, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, old_idx=4
crmd[32724]: 2007/06/18_21:04:57 info: crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=2)
crmd[32724]: 2007/06/18_21:04:57 debug: register_fsa_input_adv: crmd_ccm_msg_callback prepended FSA input 5 (I_CCM_EVENT) (cause=C_CCM_CALLBACK) with data
crmd[32724]: 2007/06/18_21:04:57 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
mgmtd[32725]: 2007/06/18_21:04:57 debug: update cib finished
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[32724]: 2007/06/18_21:04:57 debug: do_ccm_update_cache: Updating cache after CCM event 2 (NEW MEMBERSHIP).
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: NEW MEMBERSHIP: trans=2, nodes=2, new=1, lost=0 n_idx=0, new_idx=2, old_idx=4
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: 	CURRENT: guest2 [nodeid=1, born=1]
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: 	CURRENT: guest1 [nodeid=0, born=2]
mgmtd[32725]: 2007/06/18_21:04:57 debug: update cib finished
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: 	NEW:     guest1 [nodeid=0, born=2]
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_STARTED
crmd[32724]: 2007/06/18_21:04:57 info: do_started: The local CRM is operational
crmd[32724]: 2007/06/18_21:04:57 debug: register_fsa_input_adv: do_started appended FSA input 6 (I_PENDING) (cause=C_CCM_CALLBACK) without data
crmd[32724]: 2007/06/18_21:04:57 debug: s_crmd_fsa: Processing I_CCM_EVENT: [ state=S_STARTING cause=C_CCM_CALLBACK origin=crmd_ccm_msg_callback ]
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_CCM_UPDATE_CACHE
crmd[32724]: 2007/06/18_21:04:57 debug: do_ccm_update_cache: Ignoring superceeded NEW MEMBERSHIP CCM event 1 - we had 2
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_CCM_EVENT
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: NEW MEMBERSHIP: trans=1, nodes=1, new=1, lost=0 n_idx=0, new_idx=0, old_idx=3
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: 	CURRENT: guest2 [nodeid=1, born=1]
crmd[32724]: 2007/06/18_21:04:57 info: ccm_event_detail: 	NEW:     guest2 [nodeid=1, born=1]
crmd[32724]: 2007/06/18_21:04:57 debug: s_crmd_fsa: Processing I_PENDING: [ state=S_STARTING cause=C_CCM_CALLBACK origin=do_started ]
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:04:57 info: do_state_transition: State transition S_STARTING -> S_PENDING [ input=I_PENDING cause=C_CCM_CALLBACK origin=do_started ]
crmd[32724]: 2007/06/18_21:04:57 info: update_dc: Set DC to <null> (<null>)
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:04:57 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_QUERY
cib[32731]: 2007/06/18_21:04:57 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: 9725138e8d041c84abefa31d9efc82ce)
crmd[32724]: 2007/06/18_21:04:58 debug: do_cl_join_query: Querying for a DC
crmd[32724]: 2007/06/18_21:04:58 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_START
crmd[32724]: 2007/06/18_21:04:58 debug: crm_timer_start: Started Election Trigger (I_DC_TIMEOUT:30000ms), src=10
crmd[32724]: 2007/06/18_21:04:58 debug: fsa_dump_inputs: Added input: 0000000000100000 (R_CCM_DATA)
crmd[32724]: 2007/06/18_21:04:58 debug: ccm_node_update_complete: Node update 8 complete
attrd[32723]: 2007/06/18_21:05:01 info: main: Starting mainloop...
pingd[32726]: 2007/06/18_21:05:01 debug: register_with_ha: Signing in with Heartbeat
heartbeat[32708]: 2007/06/18_21:05:01 debug: APIregistration_dispatch() {
heartbeat[32708]: 2007/06/18_21:05:01 debug: process_registerevent() {
heartbeat[32708]: 2007/06/18_21:05:01 debug: client->gsource = 0x96f74e8
heartbeat[32708]: 2007/06/18_21:05:01 debug: }/*process_registerevent*/;
heartbeat[32708]: 2007/06/18_21:05:01 debug: }/*APIregistration_dispatch*/;
heartbeat[32708]: 2007/06/18_21:05:01 debug: Checking client authorization for client pingd (0:0)
heartbeat[32708]: 2007/06/18_21:05:01 debug: create_seq_snapshot_table:no missing packets found for node guest1
heartbeat[32708]: 2007/06/18_21:05:01 debug: create_seq_snapshot_table:no missing packets found for node guest2
heartbeat[32708]: 2007/06/18_21:05:01 debug: Signing on API client 32726 (pingd)
pingd[32726]: 2007/06/18_21:05:01 info: do_node_walk: Requesting the list of configured nodes
heartbeat[32708]: 2007/06/18_21:05:02 WARN: 1 lost packet(s) for [guest1] [30:32]
heartbeat[32708]: 2007/06/18_21:05:02 info: No pkts missing from guest1!
pingd[32726]: 2007/06/18_21:05:02 debug: do_node_walk: Adding: 172.16.157.1=ping
pingd[32726]: 2007/06/18_21:05:02 debug: do_node_walk: Node guest2: skipping 'normal'
pingd[32726]: 2007/06/18_21:05:03 debug: do_node_walk: Node guest1: skipping 'normal'
pingd[32726]: 2007/06/18_21:05:03 info: send_update: 1 active ping nodes
pingd[32726]: 2007/06/18_21:05:03 info: main: Starting pingd
attrd[32723]: 2007/06/18_21:05:03 debug: attrd_local_callback: update message from pingd: default_ping_set=100
attrd[32723]: 2007/06/18_21:05:03 info: find_hash_entry: Creating hash entry for default_ping_set
attrd[32723]: 2007/06/18_21:05:03 debug: find_hash_entry: 	default_ping_set->section: status
attrd[32723]: 2007/06/18_21:05:03 debug: find_hash_entry: 	default_ping_set->timeout: 5s
attrd[32723]: 2007/06/18_21:05:08 info: attrd_trigger_update: Sending flush op to all hosts for: default_ping_set
attrd[32723]: 2007/06/18_21:05:08 info: attrd_ha_callback: flush message from guest2
attrd[32723]: 2007/06/18_21:05:08 debug: find_hash_entry: 	default_ping_set->section: status
attrd[32723]: 2007/06/18_21:05:08 debug: find_hash_entry: 	default_ping_set->timeout: 5s
attrd[32723]: 2007/06/18_21:05:08 info: attrd_perform_update: Sent update 3: default_ping_set=100
crmd[32724]: 2007/06/18_21:05:09 debug: register_fsa_input_adv: handle_request appended FSA input 7 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:09 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32724]: 2007/06/18_21:05:09 debug: do_election_count_vote: Created voted hash
crmd[32724]: 2007/06/18_21:05:09 debug: do_election_count_vote: Election 2, owner: a2db98b0-fa70-4eff-990a-0f1ee9bc1430
crmd[32724]: 2007/06/18_21:05:09 info: do_election_count_vote: Election check: vote from guest1
crmd[32724]: 2007/06/18_21:05:09 debug: do_election_count_vote: Election pass: born_on
crmd[32724]: 2007/06/18_21:05:09 debug: do_election_count_vote: Election ignore: We already lost the election
crmd[32724]: 2007/06/18_21:05:09 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32724]: 2007/06/18_21:05:09 debug: do_election_check: Ignore election check: we not in an election
crmd[32724]: 2007/06/18_21:05:28 info: crm_timer_popped: Election Trigger (I_DC_TIMEOUT) just popped!
crmd[32724]: 2007/06/18_21:05:28 debug: crm_timer_stop: Stopping Election Trigger (I_DC_TIMEOUT:30000ms), src=10
crmd[32724]: 2007/06/18_21:05:28 debug: register_fsa_input_adv: crm_timer_popped appended FSA input 8 (I_DC_TIMEOUT) (cause=C_TIMER_POPPED) without data
crmd[32724]: 2007/06/18_21:05:28 debug: s_crmd_fsa: Processing I_DC_TIMEOUT: [ state=S_PENDING cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_WARN  
crmd[32724]: 2007/06/18_21:05:28 WARN: do_log: [[FSA]] Input I_DC_TIMEOUT from crm_timer_popped() received in state (S_PENDING)
crmd[32724]: 2007/06/18_21:05:28 info: do_state_transition: State transition S_PENDING -> S_ELECTION [ input=I_DC_TIMEOUT cause=C_TIMER_POPPED origin=crm_timer_popped ]
crmd[32724]: 2007/06/18_21:05:28 info: update_dc: Set DC to <null> (<null>)
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[32724]: 2007/06/18_21:05:28 debug: do_election_vote: Destroying voted hash
crmd[32724]: 2007/06/18_21:05:28 debug: crm_timer_start: Started Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[32724]: 2007/06/18_21:05:28 debug: register_fsa_input_adv: handle_request appended FSA input 9 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32724]: 2007/06/18_21:05:28 debug: do_election_count_vote: Created voted hash
crmd[32724]: 2007/06/18_21:05:28 debug: do_election_count_vote: Election 2, owner: 762a84bc-5633-4dcc-97ab-db3986cc778f
crmd[32724]: 2007/06/18_21:05:28 info: do_election_count_vote: Updated voted hash for guest2 to vote
crmd[32724]: 2007/06/18_21:05:28 info: do_election_count_vote: Election ignore: our vote (guest2)
crmd[32724]: 2007/06/18_21:05:28 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32724]: 2007/06/18_21:05:28 info: do_election_check: Still waiting on 1 non-votes (2 total)
crmd[32724]: 2007/06/18_21:05:30 debug: register_fsa_input_adv: handle_request appended FSA input 10 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32724]: 2007/06/18_21:05:30 debug: do_election_count_vote: Election 2, owner: 762a84bc-5633-4dcc-97ab-db3986cc778f
crmd[32724]: 2007/06/18_21:05:30 info: do_election_count_vote: Updated voted hash for guest1 to no-vote
crmd[32724]: 2007/06/18_21:05:30 info: do_election_count_vote: Election ignore: no-vote from guest1
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32724]: 2007/06/18_21:05:30 debug: crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms), src=11
crmd[32724]: 2007/06/18_21:05:30 debug: register_fsa_input_adv: do_election_check appended FSA input 11 (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:05:30 debug: do_election_check: Destroying voted hash
crmd[32724]: 2007/06/18_21:05:30 debug: s_crmd_fsa: Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:05:30 info: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_TE_START
crmd[32724]: 2007/06/18_21:05:30 info: start_subsystem: Starting sub-system "tengine"
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_PE_START
crmd[32724]: 2007/06/18_21:05:30 info: start_subsystem: Starting sub-system "pengine"
cib[32720]: 2007/06/18_21:05:30 info: cib_process_readwrite: We are now in R/W mode
crmd[32733]: 2007/06/18_21:05:30 debug: start_subsystem: Executing "/usr/lib/heartbeat/pengine (pengine)" (pid 32733)
cib[32720]: 2007/06/18_21:05:30 info: revision_check: Updating CIB revision to 1.3
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_START
crmd[32724]: 2007/06/18_21:05:30 debug: crm_timer_start: Started Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_DC_TAKEOVER
crmd[32724]: 2007/06/18_21:05:30 info: do_dc_takeover: Taking over DC status for this partition
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_OFFER_ALL
crmd[32724]: 2007/06/18_21:05:30 debug: initialize_join: join-1: Initializing join data (flag=true)
crmd[32724]: 2007/06/18_21:05:30 info: update_dc: Set DC to <null> (<null>)
crmd[32724]: 2007/06/18_21:05:30 info: join_make_offer: Making join offers based on membership 2
crmd[32724]: 2007/06/18_21:05:30 debug: join_make_offer: join-1: Sending offer to guest1
crmd[32724]: 2007/06/18_21:05:30 debug: join_make_offer: join-1: Sending offer to guest2
crmd[32724]: 2007/06/18_21:05:30 info: do_dc_join_offer_all: join-1: Waiting on 2 outstanding join acks
crmd[32724]: 2007/06/18_21:05:30 debug: fsa_dump_inputs: Added input: 0000000000000001 (R_THE_DC)
crmd[32724]: 2007/06/18_21:05:30 debug: fsa_dump_inputs: Added input: 0000000000000010 (R_JOIN_OK)
crmd[32724]: 2007/06/18_21:05:30 debug: fsa_dump_inputs: Added input: 0000000000000080 (R_INVOKE_PE)
crmd[32724]: 2007/06/18_21:05:30 debug: fsa_dump_inputs: Added input: 0000000000002000 (R_PE_REQUIRED)
crmd[32724]: 2007/06/18_21:05:30 debug: fsa_dump_inputs: Added input: 0000000000004000 (R_TE_REQUIRED)
crmd[32732]: 2007/06/18_21:05:30 debug: start_subsystem: Executing "/usr/lib/heartbeat/tengine (tengine)" (pid 32732)
cib[32734]: 2007/06/18_21:05:30 info: write_cib_contents: Wrote version 0.0.0 of the CIB to disk (digest: fce1ce3d0988320d4dded8ce8c5492a5)
tengine[32732]: 2007/06/18_21:05:30 debug: crm_set_env_options: HA_conn_logd_time = 60
tengine[32732]: 2007/06/18_21:05:30 info: G_main_add_SignalHandler: Added signal handler for signal 15
tengine[32732]: 2007/06/18_21:05:30 info: G_main_add_TriggerHandler: Added signal manual handler
tengine[32732]: 2007/06/18_21:05:30 debug: cib_native_signon: Connection to CIB successful
stonithd[32722]: 2007/06/18_21:05:30 debug: get_exist_client_by_chan: client_list == NULL
stonithd[32722]: 2007/06/18_21:05:30 debug: client tengine (pid=32732) succeeded to signon to stonithd.
cib[32720]: 2007/06/18_21:05:30 info: cib_null_callback: Setting cib_diff_notify callbacks for tengine: on
tengine[32732]: 2007/06/18_21:05:30 info: te_init: Registering TE UUID: aa92046a-e910-4597-949a-6d64c8b5ec61
tengine[32732]: 2007/06/18_21:05:30 info: set_graph_functions: Setting custom graph functions
tengine[32732]: 2007/06/18_21:05:30 info: unpack_graph: Unpacked transition -1: 0 actions in 0 synapses
tengine[32732]: 2007/06/18_21:05:30 info: te_init: Starting tengine
pengine[32733]: 2007/06/18_21:05:30 debug: crm_set_env_options: HA_conn_logd_time = 60
pengine[32733]: 2007/06/18_21:05:30 info: G_main_add_SignalHandler: Added signal handler for signal 15
pengine[32733]: 2007/06/18_21:05:30 debug: main: HA_record_pengine_inputs = on
pengine[32733]: 2007/06/18_21:05:30 info: pe_init: Starting pengine
crmd[32724]: 2007/06/18_21:05:30 debug: handle_request: Raising I_JOIN_OFFER: join-1
crmd[32724]: 2007/06/18_21:05:30 debug: register_fsa_input_adv: route_message appended FSA input 12 (I_JOIN_OFFER) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:30 debug: s_crmd_fsa: Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_REQUEST
crmd[32724]: 2007/06/18_21:05:30 info: update_dc: Set DC to guest2 (1.0.8)
crmd[32724]: 2007/06/18_21:05:30 debug: do_cl_join_offer_respond: do_cl_join_offer_respond added action A_DC_TIMER_STOP to the FSA
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:30 debug: join_query_callback: Respond to join offer join-1
crmd[32724]: 2007/06/18_21:05:30 debug: join_query_callback: Acknowledging guest2 as our DC
crmd[32724]: 2007/06/18_21:05:30 debug: register_fsa_input_adv: route_message appended FSA input 13 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:30 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:30 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32724]: 2007/06/18_21:05:30 debug: do_dc_join_filter_offer: Processing req from guest2
crmd[32724]: 2007/06/18_21:05:30 debug: do_dc_join_filter_offer: join-1: Welcoming node guest2 (ref join_request-crmd-1182168330-8)
crmd[32724]: 2007/06/18_21:05:30 debug: do_dc_join_filter_offer: 1 nodes have been integrated into join-1
crmd[32724]: 2007/06/18_21:05:30 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32724]: 2007/06/18_21:05:30 debug: do_dc_join_filter_offer: join-1: Still waiting on 1 outstanding offers
crmd[32724]: 2007/06/18_21:05:31 debug: register_fsa_input_adv: route_message appended FSA input 14 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:31 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:31 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32724]: 2007/06/18_21:05:31 debug: do_dc_join_filter_offer: Processing req from guest1
crmd[32724]: 2007/06/18_21:05:31 debug: do_dc_join_filter_offer: guest1 has a better generation number than the current max guest2
crmd[32724]: 2007/06/18_21:05:31 debug: log_data_element: do_dc_join_filter_offer: Max generation <generation_tuple generated="true" admin_epoch="0" epoch="0" num_updates="0" have_quorum="true" ignore_dtd="false" num_peers="2" ccm_transition="2" cib_feature_revision="1.3"/>
crmd[32724]: 2007/06/18_21:05:31 debug: log_data_element: do_dc_join_filter_offer: Their generation <generation_tuple admin_epoch="0" epoch="1" have_quorum="true" cib_feature_revision="1.3" generated="false" num_updates="0" ignore_dtd="false" num_peers="2" ccm_transition="2"/>
crmd[32724]: 2007/06/18_21:05:31 debug: do_dc_join_filter_offer: join-1: Welcoming node guest1 (ref join_request-crmd-1182168330-4)
crmd[32724]: 2007/06/18_21:05:31 debug: do_dc_join_filter_offer: 2 nodes have been integrated into join-1
crmd[32724]: 2007/06/18_21:05:31 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32724]: 2007/06/18_21:05:31 debug: check_join_state: join-1: Integration of 2 peers complete: do_dc_join_filter_offer
crmd[32724]: 2007/06/18_21:05:31 debug: register_fsa_input_adv: check_join_state prepended FSA input 15 (I_INTEGRATED) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:05:31 debug: s_crmd_fsa: Processing I_INTEGRATED: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32724]: 2007/06/18_21:05:31 info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32724]: 2007/06/18_21:05:31 info: do_state_transition: All 2 cluster nodes responded to the join offer.
crmd[32724]: 2007/06/18_21:05:31 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:31 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:31 debug: crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms), src=12
crmd[32724]: 2007/06/18_21:05:31 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_START
crmd[32724]: 2007/06/18_21:05:31 debug: crm_timer_start: Started Finalization Timer (I_ELECTION:600000ms), src=15
crmd[32724]: 2007/06/18_21:05:31 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_FINALIZE
crmd[32724]: 2007/06/18_21:05:31 debug: do_dc_join_finalize: Finializing join-1 for 2 clients
crmd[32724]: 2007/06/18_21:05:31 info: do_dc_join_finalize: join-1: Asking guest1 for its copy of the CIB
crmd[32724]: 2007/06/18_21:05:31 debug: log_data_element: do_dc_join_finalize: Requesting version <generation_tuple admin_epoch="0" epoch="1" have_quorum="true" cib_feature_revision="1.3" generated="false" num_updates="0" ignore_dtd="false" num_peers="2" ccm_transition="2"/>
crmd[32724]: 2007/06/18_21:05:31 debug: fsa_dump_inputs: Added input: 0000000000040000 (R_CIB_ASKED)
cib[32720]: 2007/06/18_21:05:32 info: cib_replace_notify: Local-only Replace: 0.1.0 from <null>
crmd[32724]: 2007/06/18_21:05:32 debug: do_cib_replaced: Updating the CIB after a replace
crmd[32724]: 2007/06/18_21:05:32 info: populate_cib_nodes: Requesting the list of configured nodes
tengine[32732]: 2007/06/18_21:05:32 debug: te_update_diff: Processing diff (cib_replace): 0.0.0 -> 0.1.0
tengine[32732]: 2007/06/18_21:05:32 debug: need_abort: Aborting on change to epoch
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs <cib epoch="1" generated="false">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs   <configuration>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     <crm_config>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       <cluster_property_set id="idCluseterPropertySet">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         <attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="symmetric-cluster" name="symmetric-cluster" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="no-quorum-policy" name="no-quorum-policy" value="ignore"/>
mgmtd[32725]: 2007/06/18_21:05:32 debug: update cib finished
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: - <cib generated="true" epoch="0"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="stonith-enabled" name="stonith-enabled" value="false"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: + <cib epoch="1" generated="false">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="short-resource-names" name="short_resource_names" value="true"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +   <configuration>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="is-managed-default" name="is-managed-default" value="true"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     <crm_config>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="transition-idle-timeout" name="transition-idle-timeout" value="120s"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       <cluster_property_set id="idCluseterPropertySet">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="default-resource-stickiness" name="default-resource-stickiness" value="0"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         <attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="stop-orphan-resources" name="stop-orphan-resources" value="true"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="symmetric-cluster" name="symmetric-cluster" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="stop-orphan-actions" name="stop-orphan-actions" value="true"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="no-quorum-policy" name="no-quorum-policy" value="ignore"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="remove-after-stop" name="remove-after-stop" value="false"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="stonith-enabled" name="stonith-enabled" value="false"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="default-resource-failure-stickiness" name="default-resource-failure-stickiness" value="-INFINITY"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="short-resource-names" name="short_resource_names" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="stonith-action" name="stonith-action" value="reboot"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="is-managed-default" name="is-managed-default" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="default-action-timeout" name="default-action-timeout" value="120s"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="transition-idle-timeout" name="transition-idle-timeout" value="120s"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="dc_deadtime" name="dc_deadtime" value="10s"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="default-resource-stickiness" name="default-resource-stickiness" value="0"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="cluster_recheck_interval" name="cluster_recheck_interval" value="0"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="stop-orphan-resources" name="stop-orphan-resources" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="election_timeout" name="election_timeout" value="2min"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="stop-orphan-actions" name="stop-orphan-actions" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="shutdown_escalation" name="shutdown_escalation" value="20min"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="remove-after-stop" name="remove-after-stop" value="false"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="crmd-integration-timeout" name="crmd-integration-timeout" value="3min"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="default-resource-failure-stickiness" name="default-resource-failure-stickiness" value="-INFINITY"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="crmd-finalization-timeout" name="crmd-finalization-timeout" value="10min"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="stonith-action" name="stonith-action" value="reboot"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="cluster-delay" name="cluster-delay" value="60s"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="default-action-timeout" name="default-action-timeout" value="120s"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="pe-error-series-max" name="pe-error-series-max" value="-1"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="dc_deadtime" name="dc_deadtime" value="10s"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="pe-warn-series-max" name="pe-warn-series-max" value="-1"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="cluster_recheck_interval" name="cluster_recheck_interval" value="0"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="pe-input-series-max" name="pe-input-series-max" value="-1"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="election_timeout" name="election_timeout" value="2min"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <nvpair id="startup-fencing" name="startup-fencing" value="true"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="shutdown_escalation" name="shutdown_escalation" value="20min"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         </attributes>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="crmd-integration-timeout" name="crmd-integration-timeout" value="3min"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       </cluster_property_set>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="crmd-finalization-timeout" name="crmd-finalization-timeout" value="10min"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     </crm_config>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="cluster-delay" name="cluster-delay" value="60s"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     <resources>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="pe-error-series-max" name="pe-error-series-max" value="-1"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       <group id="grpDummy1">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="pe-warn-series-max" name="pe-warn-series-max" value="-1"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         <primitive id="prmDummy1" class="ocf" type="Dummy" provider="heartbeat">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="pe-input-series-max" name="pe-input-series-max" value="-1"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <operations>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <nvpair id="startup-fencing" name="startup-fencing" value="true"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummy1Start" name="start" timeout="60s" on_fail="fence"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         </attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummy1Monitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       </cluster_property_set>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs             <op id="opDummy1Stop" name="stop" timeout="60s" on_fail="fence"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     </crm_config>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           </operations>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     <resources>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <instance_attributes id="atrDummy1">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       <group id="grpDummy1">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs             <attributes>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         <primitive id="prmDummy1" class="ocf" type="Dummy" provider="heartbeat">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs               <nvpair id="atrDummy11" name="delay" value="1"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <operations>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs               <nvpair id="atrDummy12" name="state" value="/var/run/heartbeat/rsctmp/Dummy1.state"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +             <op id="opDummy1Start" name="start" timeout="60s" on_fail="fence"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs             </attributes>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +             <op id="opDummy1Monitor" name="monitor" interval="10s" timeout="10s" on_fail="fence"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           </instance_attributes>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +             <op id="opDummy1Stop" name="stop" timeout="60s" on_fail="fence"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         </primitive>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           </operations>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       </group>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <instance_attributes id="atrDummy1">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     </resources>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +             <attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     <constraints>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +               <nvpair id="atrDummy11" name="delay" value="1"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       <rsc_location id="rlcDummy1" rsc="grpDummy1">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +               <nvpair id="atrDummy12" name="state" value="/var/run/heartbeat/rsctmp/Dummy1.state"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         <rule score="100" id="rulNode11">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +             </attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <expression value="guest1" attribute="#uname" operation="eq" id="expNode11"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           </instance_attributes>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         </rule>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         </primitive>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         <rule score="200" id="rulNode12">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       </group>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <expression value="guest2" attribute="#uname" operation="eq" id="expNode12"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     </resources>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         </rule>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     <constraints>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       </rsc_location>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       <rsc_location id="rlcDummy1" rsc="grpDummy1">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       <rsc_location id="ping1:disconn" rsc="grpDummy1">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         <rule score="100" id="rulNode11">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         <rule id="ping1:disconn:rule" score="-INFINITY" boolean_op="and">
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <expression value="guest1" attribute="#uname" operation="eq" id="expNode11"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <expression id="ping1:disconn:expr:defined" attribute="default_ping_set" operation="defined"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         </rule>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs           <expression id="ping1:disconn:expr:positive" attribute="default_ping_set" operation="lt" value="100"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         <rule score="200" id="rulNode12">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs         </rule>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <expression value="guest2" attribute="#uname" operation="eq" id="expNode12"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs       </rsc_location>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         </rule>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     </constraints>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       </rsc_location>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs   </configuration>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       <rsc_location id="ping1:disconn" rsc="grpDummy1">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs   <status>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         <rule id="ping1:disconn:rule" score="-INFINITY" boolean_op="and">
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs     <node_state shutdown="0" id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <expression id="ping1:disconn:expr:defined" attribute="default_ping_set" operation="defined"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs   </status>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +           <expression id="ping1:disconn:expr:positive" attribute="default_ping_set" operation="lt" value="100"/>
tengine[32732]: 2007/06/18_21:05:32 debug: log_data_element: need_abort: Abort: CIB Attrs </cib>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +         </rule>
tengine[32732]: 2007/06/18_21:05:32 info: update_abort_priority: Abort priority upgraded to 1000000
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +       </rsc_location>
tengine[32732]: 2007/06/18_21:05:32 info: update_abort_priority: 'DC Takeover' abort superceeded
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     </constraints>
tengine[32732]: 2007/06/18_21:05:32 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +   </configuration>
tengine[32732]: 2007/06/18_21:05:32 debug: notify_crmd: Transition -1 status: te_abort - Non-status change
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +   <status>
tengine[32732]: 2007/06/18_21:05:32 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +     <node_state shutdown="0" id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430"/>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:32 debug: log_data_element: cib:diff: + </cib>
cib[32735]: 2007/06/18_21:05:33 info: write_cib_contents: Wrote version 0.1.0 of the CIB to disk (digest: 5271c399ff6b67e41ba9b9918f2ba1bd)
crmd[32724]: 2007/06/18_21:05:33 debug: populate_cib_nodes: Node 172.16.157.1: skipping 'ping'
crmd[32724]: 2007/06/18_21:05:33 notice: populate_cib_nodes: Node: guest2 (uuid: 762a84bc-5633-4dcc-97ab-db3986cc778f)
crmd[32724]: 2007/06/18_21:05:33 notice: populate_cib_nodes: Node: guest1 (uuid: a2db98b0-fa70-4eff-990a-0f1ee9bc1430)
crmd[32724]: 2007/06/18_21:05:33 debug: register_fsa_input_adv: do_cib_replaced appended FSA input 16 (I_ELECTION) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:05:33 debug: check_join_state: Invoked by finalize_sync_callback in state: S_FINALIZE_JOIN
crmd[32724]: 2007/06/18_21:05:33 debug: check_join_state: join-1: Still waiting on 2 integrated nodes
crmd[32724]: 2007/06/18_21:05:33 debug: finalize_join: Notifying 2 clients of join-1 results
crmd[32724]: 2007/06/18_21:05:33 debug: finalize_join_for: join-1: ACK'ing join request from guest1, state member
crmd[32724]: 2007/06/18_21:05:33 debug: finalize_join_for: join-1: ACK'ing join request from guest2, state member
crmd[32724]: 2007/06/18_21:05:33 info: update_attrd: Connecting to attrd...
attrd[32723]: 2007/06/18_21:05:33 info: attrd_local_callback: Sending full refresh
crmd[32724]: 2007/06/18_21:05:33 debug: update_attrd: sent attrd refresh
attrd[32723]: 2007/06/18_21:05:33 info: attrd_trigger_update: Sending flush op to all hosts for: default_ping_set
crmd[32724]: 2007/06/18_21:05:33 debug: s_crmd_fsa: Processing I_ELECTION: [ state=S_FINALIZE_JOIN cause=C_FSA_INTERNAL origin=do_cib_replaced ]
crmd[32724]: 2007/06/18_21:05:33 info: do_state_transition: State transition S_FINALIZE_JOIN -> S_ELECTION [ input=I_ELECTION cause=C_FSA_INTERNAL origin=do_cib_replaced ]
crmd[32724]: 2007/06/18_21:05:33 info: update_dc: Set DC to <null> (<null>)
crmd[32724]: 2007/06/18_21:05:33 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:33 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:33 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:33 debug: crm_timer_stop: Stopping Finalization Timer (I_ELECTION:600000ms), src=15
crmd[32724]: 2007/06/18_21:05:33 debug: do_fsa_action: actions:trace: 	// A_ELECTION_VOTE
crmd[32724]: 2007/06/18_21:05:33 debug: do_election_vote: Destroying voted hash
crmd[32724]: 2007/06/18_21:05:33 debug: crm_timer_start: Started Election Timeout (I_ELECTION_DC:120000ms), src=16
crmd[32724]: 2007/06/18_21:05:33 debug: handle_request: Transition cancelled: te_abort/Non-status change
crmd[32724]: 2007/06/18_21:05:33 debug: handle_request: Filtering te_abort op in state S_ELECTION
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: - <cib num_updates="0"/>
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: + <cib num_updates="1">
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: +   <status>
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: +     <node_state join="pending" id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430"/>
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: +     <node_state join="pending" id="762a84bc-5633-4dcc-97ab-db3986cc778f"/>
mgmtd[32725]: 2007/06/18_21:05:33 debug: update cib finished
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: +   </status>
crmd[32724]: 2007/06/18_21:05:33 debug: ccm_node_update_complete: Node update 16 complete
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:33 debug: send_peer_reply: Sending update diff 0.1.0 -> 0.1.1
tengine[32732]: 2007/06/18_21:05:33 debug: te_update_diff: Processing diff (cib_update): 0.1.0 -> 0.1.1
mgmtd[32725]: 2007/06/18_21:05:33 debug: update cib finished
tengine[32732]: 2007/06/18_21:05:33 debug: te_update_diff: Processing diff (cib_update): 0.1.1 -> 0.1.2
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: - <cib generated="false" num_updates="1"/>
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: + <cib generated="true" num_updates="2" dc_uuid="762a84bc-5633-4dcc-97ab-db3986cc778f"/>
cib[32720]: 2007/06/18_21:05:33 debug: send_peer_reply: Sending update diff 0.1.1 -> 0.1.2
mgmtd[32725]: 2007/06/18_21:05:33 debug: update cib finished
tengine[32732]: 2007/06/18_21:05:33 debug: te_update_diff: Processing diff (cib_bump): 0.1.2 -> 0.2.3
tengine[32732]: 2007/06/18_21:05:33 debug: need_abort: Aborting on change to epoch
tengine[32732]: 2007/06/18_21:05:33 debug: log_data_element: need_abort: Abort: CIB Attrs <cib epoch="2" num_updates="3"/>
crmd[32724]: 2007/06/18_21:05:33 debug: handle_request: Transition cancelled: te_abort/(null)
tengine[32732]: 2007/06/18_21:05:33 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
crmd[32724]: 2007/06/18_21:05:33 debug: handle_request: Filtering te_abort op in state S_ELECTION
tengine[32732]: 2007/06/18_21:05:33 debug: notify_crmd: Transition -1 status: te_abort - <null>
tengine[32732]: 2007/06/18_21:05:33 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: - <cib epoch="1" num_updates="2"/>
cib[32720]: 2007/06/18_21:05:33 debug: log_data_element: cib:diff: + <cib epoch="2" num_updates="3"/>
cib[32720]: 2007/06/18_21:05:33 debug: send_peer_reply: Sending update diff 0.1.2 -> 0.2.3
cib[32736]: 2007/06/18_21:05:33 info: write_cib_contents: Wrote version 0.2.3 of the CIB to disk (digest: 483c32fc85e687f42c7961b985b1fe64)
attrd[32723]: 2007/06/18_21:05:34 info: attrd_ha_callback: flush message from guest2
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Raising I_JOIN_RESULT: join-1
attrd[32723]: 2007/06/18_21:05:34 debug: find_hash_entry: 	default_ping_set->section: status
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: route_message appended FSA input 17 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
attrd[32723]: 2007/06/18_21:05:34 debug: find_hash_entry: 	default_ping_set->timeout: 5s
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: handle_request appended FSA input 18 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:34 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_ELECTION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32724]: 2007/06/18_21:05:34 debug: do_election_count_vote: Created voted hash
crmd[32724]: 2007/06/18_21:05:34 debug: do_election_count_vote: Election 3, owner: 762a84bc-5633-4dcc-97ab-db3986cc778f
crmd[32724]: 2007/06/18_21:05:34 info: do_election_count_vote: Updated voted hash for guest2 to vote
crmd[32724]: 2007/06/18_21:05:34 info: do_election_count_vote: Election ignore: our vote (guest2)
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32724]: 2007/06/18_21:05:34 info: do_election_check: Still waiting on 1 non-votes (2 total)
attrd[32723]: 2007/06/18_21:05:34 info: attrd_perform_update: Sent update 5: default_ping_set=100
mgmtd[32725]: 2007/06/18_21:05:34 debug: update cib finished
tengine[32732]: 2007/06/18_21:05:34 debug: te_update_diff: Processing diff (cib_modify): 0.2.3 -> 0.2.4
tengine[32732]: 2007/06/18_21:05:34 info: extract_event: Aborting on transient_attributes changes for 762a84bc-5633-4dcc-97ab-db3986cc778f
tengine[32732]: 2007/06/18_21:05:34 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="762a84bc-5633-4dcc-97ab-db3986cc778f">
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Transition cancelled: te_abort/(null)
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-762a84bc-5633-4dcc-97ab-db3986cc778f">
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Filtering te_abort op in state S_ELECTION
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause     <attributes>
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-762a84bc-5633-4dcc-97ab-db3986cc778f-default_ping_set" name="default_ping_set" value="100"/>
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause     </attributes>
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
tengine[32732]: 2007/06/18_21:05:34 debug: notify_crmd: Transition -1 status: te_abort - <null>
tengine[32732]: 2007/06/18_21:05:34 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: - <cib num_updates="3"/>
attrd[32723]: 2007/06/18_21:05:34 debug: attrd_cib_callback: Update 5 for default_ping_set passed
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: + <cib num_updates="4">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +   <status>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +     <node_state id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +       <transient_attributes id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +         <instance_attributes id="status-762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +           <attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +             <nvpair id="status-762a84bc-5633-4dcc-97ab-db3986cc778f-default_ping_set" name="default_ping_set" value="100"/>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +           </attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +         </instance_attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +       </transient_attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:34 debug: send_peer_reply: Sending update diff 0.2.3 -> 0.2.4
cib[32737]: 2007/06/18_21:05:34 info: write_cib_contents: Wrote version 0.2.4 of the CIB to disk (digest: bbd22751391f0616069ab17bea5df6d6)
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: route_message appended FSA input 19 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: handle_request appended FSA input 20 (I_NULL) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:34 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_ELECTION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_ELECTION_COUNT
crmd[32724]: 2007/06/18_21:05:34 debug: do_election_count_vote: Election 3, owner: 762a84bc-5633-4dcc-97ab-db3986cc778f
crmd[32724]: 2007/06/18_21:05:34 info: do_election_count_vote: Updated voted hash for guest1 to no-vote
crmd[32724]: 2007/06/18_21:05:34 info: do_election_count_vote: Election ignore: no-vote from guest1
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_ELECTION_CHECK
crmd[32724]: 2007/06/18_21:05:34 debug: crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms), src=16
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: do_election_check appended FSA input 21 (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:05:34 debug: do_election_check: Destroying voted hash
crmd[32724]: 2007/06/18_21:05:34 debug: s_crmd_fsa: Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:05:34 info: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_TE_START
crmd[32724]: 2007/06/18_21:05:34 info: start_subsystem: Starting sub-system "tengine"
crmd[32724]: 2007/06/18_21:05:34 WARN: start_subsystem: Client tengine already running as pid 32732
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_PE_START
mgmtd[32725]: 2007/06/18_21:05:34 debug: update cib finished
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: - <cib num_updates="4"/>
crmd[32724]: 2007/06/18_21:05:34 info: start_subsystem: Starting sub-system "pengine"
tengine[32732]: 2007/06/18_21:05:34 debug: te_update_diff: Processing diff (cib_modify): 0.2.4 -> 0.2.5
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: + <cib num_updates="5">
crmd[32724]: 2007/06/18_21:05:34 WARN: start_subsystem: Client pengine already running as pid 32733
tengine[32732]: 2007/06/18_21:05:34 info: extract_event: Aborting on transient_attributes changes for a2db98b0-fa70-4eff-990a-0f1ee9bc1430
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:34 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +     <node_state id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_START
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +       <transient_attributes id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:34 debug: crm_timer_start: Started Integration Timer (I_INTEGRATED:180000ms), src=17
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +         <instance_attributes id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause     <attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +           <attributes>
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_DC_TAKEOVER
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430-default_ping_set" name="default_ping_set" value="100"/>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +             <nvpair id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430-default_ping_set" name="default_ping_set" value="100"/>
crmd[32724]: 2007/06/18_21:05:34 info: do_dc_takeover: Taking over DC status for this partition
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +           </attributes>
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_OFFER_ALL
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +         </instance_attributes>
crmd[32724]: 2007/06/18_21:05:34 debug: initialize_join: join-2: Initializing join data (flag=true)
tengine[32732]: 2007/06/18_21:05:34 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +       </transient_attributes>
crmd[32724]: 2007/06/18_21:05:34 info: update_dc: Set DC to <null> (<null>)
tengine[32732]: 2007/06/18_21:05:34 debug: notify_crmd: Transition -1 status: te_abort - <null>
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +     </node_state>
crmd[32724]: 2007/06/18_21:05:34 debug: join_make_offer: join-2: Sending offer to guest1
tengine[32732]: 2007/06/18_21:05:34 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: +   </status>
crmd[32724]: 2007/06/18_21:05:34 debug: join_make_offer: join-2: Sending offer to guest2
cib[32720]: 2007/06/18_21:05:34 debug: log_data_element: cib:diff: + </cib>
crmd[32724]: 2007/06/18_21:05:34 info: do_dc_join_offer_all: join-2: Waiting on 2 outstanding join acks
cib[32720]: 2007/06/18_21:05:34 debug: send_peer_reply: Sending update diff 0.2.4 -> 0.2.5
crmd[32724]: 2007/06/18_21:05:34 debug: fsa_dump_inputs: Removed input: 0000000000020000 (R_HAVE_CIB)
cib[32720]: 2007/06/18_21:05:34 info: cib_process_readwrite: We are now in R/O mode
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Transition cancelled: te_abort/(null)
cib[32720]: 2007/06/18_21:05:34 info: cib_process_readwrite: We are now in R/W mode
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Filtering te_abort op in state S_INTEGRATION
cib[32738]: 2007/06/18_21:05:34 info: write_cib_contents: Wrote version 0.2.5 of the CIB to disk (digest: e23f458ada68cf08afab1c21d59766b5)
crmd[32724]: 2007/06/18_21:05:34 debug: handle_request: Raising I_JOIN_OFFER: join-2
crmd[32724]: 2007/06/18_21:05:34 debug: register_fsa_input_adv: route_message appended FSA input 22 (I_JOIN_OFFER) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:34 debug: s_crmd_fsa: Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_REQUEST
crmd[32724]: 2007/06/18_21:05:34 info: update_dc: Set DC to guest2 (1.0.8)
crmd[32724]: 2007/06/18_21:05:34 debug: do_cl_join_offer_respond: do_cl_join_offer_respond added action A_DC_TIMER_STOP to the FSA
crmd[32724]: 2007/06/18_21:05:34 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:35 debug: join_query_callback: Respond to join offer join-2
crmd[32724]: 2007/06/18_21:05:35 debug: join_query_callback: Acknowledging guest2 as our DC
crmd[32724]: 2007/06/18_21:05:35 debug: register_fsa_input_adv: route_message appended FSA input 23 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:35 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:35 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32724]: 2007/06/18_21:05:35 debug: do_dc_join_filter_offer: Processing req from guest2
crmd[32724]: 2007/06/18_21:05:35 debug: do_dc_join_filter_offer: join-2: Welcoming node guest2 (ref join_request-crmd-1182168335-14)
crmd[32724]: 2007/06/18_21:05:35 debug: do_dc_join_filter_offer: 1 nodes have been integrated into join-2
crmd[32724]: 2007/06/18_21:05:35 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32724]: 2007/06/18_21:05:35 debug: do_dc_join_filter_offer: join-2: Still waiting on 1 outstanding offers
crmd[32724]: 2007/06/18_21:05:36 debug: register_fsa_input_adv: route_message appended FSA input 24 (I_JOIN_REQUEST) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:36 debug: s_crmd_fsa: Processing I_JOIN_REQUEST: [ state=S_INTEGRATION cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_REQ
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_filter_offer: Processing req from guest1
cib[32720]: 2007/06/18_21:05:36 info: sync_our_cib: Syncing CIB to all peers
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_filter_offer: join-2: Welcoming node guest1 (ref join_request-crmd-1182168334-7)
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_filter_offer: 2 nodes have been integrated into join-2
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: Invoked by do_dc_join_filter_offer in state: S_INTEGRATION
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: join-2: Integration of 2 peers complete: do_dc_join_filter_offer
crmd[32724]: 2007/06/18_21:05:36 debug: register_fsa_input_adv: check_join_state prepended FSA input 25 (I_INTEGRATED) (cause=C_FSA_INTERNAL) without data
crmd[32724]: 2007/06/18_21:05:36 debug: s_crmd_fsa: Processing I_INTEGRATED: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32724]: 2007/06/18_21:05:36 info: do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ]
crmd[32724]: 2007/06/18_21:05:36 info: do_state_transition: All 2 cluster nodes responded to the join offer.
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
attrd[32723]: 2007/06/18_21:05:36 info: attrd_local_callback: Sending full refresh
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
attrd[32723]: 2007/06/18_21:05:36 info: attrd_trigger_update: Sending flush op to all hosts for: default_ping_set
crmd[32724]: 2007/06/18_21:05:36 debug: crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms), src=17
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_START
crmd[32724]: 2007/06/18_21:05:36 debug: crm_timer_start: Started Finalization Timer (I_ELECTION:600000ms), src=18
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_FINALIZE
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_finalize: Finializing join-2 for 2 clients
crmd[32724]: 2007/06/18_21:05:36 debug: update_attrd: sent attrd refresh
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: Invoked by do_dc_join_finalize in state: S_FINALIZE_JOIN
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: join-2: Still waiting on 2 integrated nodes
crmd[32724]: 2007/06/18_21:05:36 debug: finalize_join: Notifying 2 clients of join-2 results
crmd[32724]: 2007/06/18_21:05:36 debug: finalize_join_for: join-2: ACK'ing join request from guest1, state member
crmd[32724]: 2007/06/18_21:05:36 debug: finalize_join_for: join-2: ACK'ing join request from guest2, state member
crmd[32724]: 2007/06/18_21:05:36 debug: fsa_dump_inputs: Added input: 0000000000020000 (R_HAVE_CIB)
mgmtd[32725]: 2007/06/18_21:05:36 debug: update cib finished
crmd[32724]: 2007/06/18_21:05:36 debug: handle_request: Transition cancelled: te_abort/(null)
tengine[32732]: 2007/06/18_21:05:36 debug: te_update_diff: Processing diff (cib_bump): 0.2.5 -> 0.3.6
crmd[32724]: 2007/06/18_21:05:36 debug: handle_request: Filtering te_abort op in state S_FINALIZE_JOIN
tengine[32732]: 2007/06/18_21:05:36 debug: need_abort: Aborting on change to epoch
tengine[32732]: 2007/06/18_21:05:36 debug: log_data_element: need_abort: Abort: CIB Attrs <cib epoch="3" num_updates="6"/>
tengine[32732]: 2007/06/18_21:05:36 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
tengine[32732]: 2007/06/18_21:05:36 debug: notify_crmd: Transition -1 status: te_abort - <null>
tengine[32732]: 2007/06/18_21:05:36 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: - <cib epoch="2" num_updates="5"/>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: + <cib epoch="3" num_updates="6"/>
cib[32720]: 2007/06/18_21:05:36 debug: send_peer_reply: Sending update diff 0.2.5 -> 0.3.6
cib[32739]: 2007/06/18_21:05:36 info: write_cib_contents: Wrote version 0.3.6 of the CIB to disk (digest: d18f73d8f2928b09cd04ad095cc719c3)
attrd[32723]: 2007/06/18_21:05:36 info: attrd_ha_callback: flush message from guest2
crmd[32724]: 2007/06/18_21:05:36 debug: handle_request: Raising I_JOIN_RESULT: join-2
attrd[32723]: 2007/06/18_21:05:36 debug: find_hash_entry: 	default_ping_set->section: status
crmd[32724]: 2007/06/18_21:05:36 debug: register_fsa_input_adv: route_message appended FSA input 26 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
attrd[32723]: 2007/06/18_21:05:36 debug: find_hash_entry: 	default_ping_set->timeout: 5s
crmd[32724]: 2007/06/18_21:05:36 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32724]: 2007/06/18_21:05:36 info: update_dc: Set DC to guest2 (1.0.8)
crmd[32724]: 2007/06/18_21:05:36 debug: do_cl_join_finalize_respond: Confirming join join-2: join_ack_nack
crmd[32724]: 2007/06/18_21:05:36 debug: do_cl_join_finalize_respond: join-2: Join complete.  Sending local LRM status.
attrd[32723]: 2007/06/18_21:05:36 info: attrd_perform_update: Sent update 7: default_ping_set=100
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_ack: Ignoring op=join_ack_nack message
attrd[32723]: 2007/06/18_21:05:36 debug: attrd_cib_callback: Update 7 for default_ping_set passed
cib[32740]: 2007/06/18_21:05:36 info: write_cib_contents: Wrote version 0.3.6 of the CIB to disk (digest: d18f73d8f2928b09cd04ad095cc719c3)
crmd[32724]: 2007/06/18_21:05:36 debug: register_fsa_input_adv: route_message appended FSA input 27 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:36 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32724]: 2007/06/18_21:05:36 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32724]: 2007/06/18_21:05:36 info: do_dc_join_ack: join-2: Updating node state to member for guest2
crmd[32724]: 2007/06/18_21:05:36 debug: do_dc_join_ack: join-2: Registered callback for LRM update 30
mgmtd[32725]: 2007/06/18_21:05:36 debug: update cib finished
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: - <cib num_updates="6">
tengine[32732]: 2007/06/18_21:05:36 debug: te_update_diff: Processing diff (cib_update): 0.3.6 -> 0.3.7
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: -   <status>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: -     <node_state join="pending" id="762a84bc-5633-4dcc-97ab-db3986cc778f"/>
crmd[32724]: 2007/06/18_21:05:36 debug: join_update_complete_callback: Join update 30 complete
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: -   </status>
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: - </cib>
crmd[32724]: 2007/06/18_21:05:36 debug: check_join_state: join-2: Still waiting on 1 confirmations
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: + <cib num_updates="7">
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +   <status>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +     <node_state join="member" ha="active" expected="member" id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +       <lrm id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +         <lrm_resources/>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +       </lrm>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:36 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:36 debug: send_peer_reply: Sending update diff 0.3.6 -> 0.3.7
cib[32741]: 2007/06/18_21:05:36 info: write_cib_contents: Wrote version 0.3.7 of the CIB to disk (digest: 83ca72347157f40a98e9cd62bd8e7837)
crmd[32724]: 2007/06/18_21:05:37 debug: register_fsa_input_adv: route_message appended FSA input 28 (I_JOIN_RESULT) (cause=C_HA_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:37 debug: s_crmd_fsa: Processing I_JOIN_RESULT: [ state=S_FINALIZE_JOIN cause=C_HA_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_CL_JOIN_RESULT
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_DC_JOIN_PROCESS_ACK
crmd[32724]: 2007/06/18_21:05:37 info: do_dc_join_ack: join-2: Updating node state to member for guest1
crmd[32724]: 2007/06/18_21:05:37 debug: do_dc_join_ack: join-2: Registered callback for LRM update 31
mgmtd[32725]: 2007/06/18_21:05:37 debug: update cib finished
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: - <cib num_updates="7">
crmd[32724]: 2007/06/18_21:05:37 debug: join_update_complete_callback: Join update 31 complete
tengine[32732]: 2007/06/18_21:05:37 debug: te_update_diff: Processing diff (cib_update): 0.3.7 -> 0.3.8
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: -   <status>
crmd[32724]: 2007/06/18_21:05:37 debug: check_join_state: Invoked by join_update_complete_callback in state: S_FINALIZE_JOIN
tengine[32732]: 2007/06/18_21:05:37 debug: abort_transition_graph: process_te_message:276 - Triggered graph processing : Peer Cancelled
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: -     <node_state join="pending" id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430"/>
crmd[32724]: 2007/06/18_21:05:37 debug: check_join_state: join-2 complete: join_update_complete_callback
tengine[32732]: 2007/06/18_21:05:37 debug: notify_crmd: Transition -1 status: te_abort - <null>
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: -   </status>
crmd[32724]: 2007/06/18_21:05:37 debug: register_fsa_input_adv: check_join_state appended FSA input 29 (I_FINALIZED) (cause=C_FSA_INTERNAL) without data
tengine[32732]: 2007/06/18_21:05:37 debug: print_graph: ## Empty transition graph ##
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: - </cib>
crmd[32724]: 2007/06/18_21:05:37 debug: s_crmd_fsa: Processing I_FINALIZED: [ state=S_FINALIZE_JOIN cause=C_FSA_INTERNAL origin=check_join_state ]
pengine[32733]: 2007/06/18_21:05:37 debug: unpack_config: Default action timeout: 120s
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: + <cib num_updates="8">
crmd[32724]: 2007/06/18_21:05:37 info: do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ]
pengine[32733]: 2007/06/18_21:05:37 debug: unpack_config: Default stickiness: 0
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:37 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
pengine[32733]: 2007/06/18_21:05:37 debug: unpack_config: Default failure stickiness: -1000000
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +     <node_state join="member" ha="active" expected="member" id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[32733]: 2007/06/18_21:05:37 debug: unpack_config: STONITH of failed nodes is disabled
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +       <lrm id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:37 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-0.bz2
pengine[32733]: 2007/06/18_21:05:37 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +         <lrm_resources/>
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:37 info: unpack_graph: Unpacked transition 0: 9 actions in 9 synapses
pengine[32733]: 2007/06/18_21:05:37 notice: unpack_config: On loss of CCM Quorum: Ignore
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +       </lrm>
crmd[32724]: 2007/06/18_21:05:37 debug: crm_timer_stop: Stopping Finalization Timer (I_ELECTION:600000ms), src=18
tengine[32732]: 2007/06/18_21:05:37 debug: initiate_action: Action 3: Increasing IDLE timer to 240000
pengine[32733]: 2007/06/18_21:05:37 info: determine_online_status: Node guest1 is online
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +     </node_state>
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_TE_CANCEL
tengine[32732]: 2007/06/18_21:05:37 info: send_rsc_command: Initiating action 3: prmDummy1_monitor_0 on guest2
pengine[32733]: 2007/06/18_21:05:37 info: determine_online_status: Node guest2 is online
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: +   </status>
crmd[32724]: 2007/06/18_21:05:37 debug: do_te_invoke: Cancelling the active Transition
tengine[32732]: 2007/06/18_21:05:37 debug: send_rsc_command: Action 3: Increasing transition 0 timeout to 300000 (2*120000 + 60000)
pengine[32733]: 2007/06/18_21:05:37 info: group_print: Resource Group: grpDummy1
cib[32720]: 2007/06/18_21:05:37 debug: log_data_element: cib:diff: + </cib>
crmd[32724]: 2007/06/18_21:05:37 debug: handle_request: Transition cancelled: te_abort/(null)
tengine[32732]: 2007/06/18_21:05:37 info: send_rsc_command: Initiating action 5: prmDummy1_monitor_0 on guest1
pengine[32733]: 2007/06/18_21:05:37 info: native_print:     prmDummy1	(heartbeat::ocf:Dummy):	Stopped 
cib[32720]: 2007/06/18_21:05:37 debug: send_peer_reply: Sending update diff 0.3.7 -> 0.3.8
crmd[32724]: 2007/06/18_21:05:37 debug: register_fsa_input_adv: route_message appended FSA input 30 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:05:37 debug: run_graph: Transition 0: (Complete=0, Pending=0, Fired=2, Skipped=0, Incomplete=7)
pengine[32733]: 2007/06/18_21:05:37 debug: group_rsc_location: Processing rsc_location rulNode11 for grpDummy1
crmd[32724]: 2007/06/18_21:05:37 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[32733]: 2007/06/18_21:05:37 debug: group_rsc_location: Processing rsc_location rulNode12 for grpDummy1
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
pengine[32733]: 2007/06/18_21:05:37 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy1
crmd[32724]: 2007/06/18_21:05:37 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
pengine[32733]: 2007/06/18_21:05:37 debug: native_print: Allocating: prmDummy1	(heartbeat::ocf:Dummy):	Stopped 
crmd[32724]: 2007/06/18_21:05:37 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1182168337-19
pengine[32733]: 2007/06/18_21:05:37 debug: native_assign_node: Color prmDummy1, Node[0] guest2: 200
crmd[32724]: 2007/06/18_21:05:37 debug: register_fsa_input_adv: route_message appended FSA input 31 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[32733]: 2007/06/18_21:05:37 debug: native_assign_node: Color prmDummy1, Node[1] guest1: 100
crmd[32724]: 2007/06/18_21:05:37 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[32733]: 2007/06/18_21:05:37 debug: native_assign_node: Assigning guest2 to prmDummy1
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_LOG   
pengine[32733]: 2007/06/18_21:05:37 notice: StartRsc:  guest2	Start prmDummy1
crmd[32724]: 2007/06/18_21:05:37 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
pengine[32733]: 2007/06/18_21:05:37 notice: RecurringOp: guest2	   prmDummy1_monitor_10000
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[32733]: 2007/06/18_21:05:37 debug: get_last_sequence: Series file /var/lib/heartbeat/pengine/pe-input.last does not exist
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
pengine[32733]: 2007/06/18_21:05:37 info: process_pe_message: Transition 0: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-0.bz2
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:37 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
crmd[32724]: 2007/06/18_21:05:37 debug: do_te_invoke: Starting a transition
crmd[32724]: 2007/06/18_21:05:37 debug: get_lrm_resource: Adding rsc prmDummy1 before operation
lrmd[32721]: 2007/06/18_21:05:37 debug: on_msg_add_rsc:client [32724] adds resource prmDummy1
crmd[32724]: 2007/06/18_21:05:37 info: do_lrm_rsc_op: Performing op=prmDummy1_monitor_0 key=3:0:aa92046a-e910-4597-949a-6d64c8b5ec61)
lrmd[32721]: 2007/06/18_21:05:37 debug: on_msg_perform_op: add an operation operation monitor[2] on ocf::Dummy::prmDummy1 for client 32724, its parameters: CRM_meta_op_target_rc=[7] state=[/var/run/heartbeat/rsctmp/Dummy1.state] delay=[1] CRM_meta_timeout=[120000] crm_feature_set=[1.0.8]  to the operation list.
cib[32742]: 2007/06/18_21:05:37 info: write_cib_contents: Wrote version 0.3.8 of the CIB to disk (digest: ab0125a936fa7a6a6e23b5bb47f0a45a)
lrmd[32721]: 2007/06/18_21:05:38 WARN: Exiting prmDummy1:monitor process 32743 returned rc 7.
crmd[32724]: 2007/06/18_21:05:38 info: process_lrm_event: LRM operation prmDummy1_monitor_0 (call=2, rc=7) complete 
crmd[32724]: 2007/06/18_21:05:38 debug: do_update_resource: Sent resource state update message: 33
tengine[32732]: 2007/06/18_21:05:38 debug: te_update_diff: Processing diff (cib_update): 0.3.8 -> 0.3.9
mgmtd[32725]: 2007/06/18_21:05:38 debug: update cib finished
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: - <cib num_updates="8"/>
crmd[32724]: 2007/06/18_21:05:38 debug: process_lrm_event: Op prmDummy1_monitor_0 (call=2): confirmed
tengine[32732]: 2007/06/18_21:05:38 info: match_graph_event: Action prmDummy1_monitor_0 (3) confirmed on 762a84bc-5633-4dcc-97ab-db3986cc778f
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: + <cib num_updates="9">
tengine[32732]: 2007/06/18_21:05:38 info: send_rsc_command: Initiating action 2: probe_complete on guest2
tengine[32732]: 2007/06/18_21:05:38 debug: send_rsc_command: Skipping wait for 2
tengine[32732]: 2007/06/18_21:05:38 debug: run_graph: Transition 0: (Complete=1, Pending=1, Fired=1, Skipped=0, Incomplete=6)
tengine[32732]: 2007/06/18_21:05:38 debug: run_graph: Transition 0: (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=6)
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:38 debug: cib_rsc_callback: Resource update 33 complete
mgmtd[32725]: 2007/06/18_21:05:38 debug: update cib finished
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +     <node_state id="762a84bc-5633-4dcc-97ab-db3986cc778f">
tengine[32732]: 2007/06/18_21:05:39 debug: te_update_diff: Processing diff (cib_modify): 0.3.9 -> 0.3.10
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +       <lrm id="762a84bc-5633-4dcc-97ab-db3986cc778f">
tengine[32732]: 2007/06/18_21:05:39 info: extract_event: Aborting on transient_attributes changes for 762a84bc-5633-4dcc-97ab-db3986cc778f
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +         <lrm_resources>
tengine[32732]: 2007/06/18_21:05:39 info: update_abort_priority: Abort priority upgraded to 1000000
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummy1" type="Dummy" class="ocf" provider="heartbeat">
tengine[32732]: 2007/06/18_21:05:39 info: update_abort_priority: Abort action 0 superceeded by 2
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummy1_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="3:0:aa92046a-e910-4597-949a-6d64c8b5ec61" transition_magic="0:7;3:0:aa92046a-e910-4597-949a-6d64c8b5ec61" call_id="2" crm_feature_set="1.0.8" rc_code="7" op_status="0" interval="0" op_digest="c47037b095f8872488876d9dae9d7b2f"/>
tengine[32732]: 2007/06/18_21:05:39 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +           </lrm_resource>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +         </lrm_resources>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +       </lrm>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause     <attributes>
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +     </node_state>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-762a84bc-5633-4dcc-97ab-db3986cc778f-probe_complete" name="probe_complete" value="true"/>
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: +   </status>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[32720]: 2007/06/18_21:05:38 debug: log_data_element: cib:diff: + </cib>
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[32720]: 2007/06/18_21:05:38 debug: send_peer_reply: Sending update diff 0.3.8 -> 0.3.9
tengine[32732]: 2007/06/18_21:05:39 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: - <cib num_updates="9"/>
tengine[32732]: 2007/06/18_21:05:39 debug: run_graph: Transition 0: (Complete=2, Pending=1, Fired=0, Skipped=5, Incomplete=1)
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: + <cib num_updates="10">
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +   <status>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +     <node_state id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +       <transient_attributes id="762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +         <instance_attributes id="status-762a84bc-5633-4dcc-97ab-db3986cc778f">
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +           <attributes>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +             <nvpair id="status-762a84bc-5633-4dcc-97ab-db3986cc778f-probe_complete" name="probe_complete" value="true"/>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +           </attributes>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +         </instance_attributes>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +       </transient_attributes>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:39 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:39 debug: send_peer_reply: Sending update diff 0.3.9 -> 0.3.10
cib[32747]: 2007/06/18_21:05:39 info: write_cib_contents: Wrote version 0.3.10 of the CIB to disk (digest: f9c2107c22ef0fecc272f7ffb914e192)
mgmtd[32725]: 2007/06/18_21:05:40 debug: update cib finished
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: - <cib num_updates="10"/>
crmd[32724]: 2007/06/18_21:05:40 debug: handle_request: Transition cancelled: te_abort/transient_attributes
tengine[32732]: 2007/06/18_21:05:40 debug: te_update_diff: Processing diff (cib_update): 0.3.10 -> 0.3.11
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: + <cib num_updates="11">
crmd[32724]: 2007/06/18_21:05:40 debug: register_fsa_input_adv: route_message appended FSA input 32 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:05:40 info: match_graph_event: Action prmDummy1_monitor_0 (5) confirmed on a2db98b0-fa70-4eff-990a-0f1ee9bc1430
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:40 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:40 info: send_rsc_command: Initiating action 4: probe_complete on guest1
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +     <node_state id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:40 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:40 debug: send_rsc_command: Skipping wait for 4
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +       <lrm id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
crmd[32724]: 2007/06/18_21:05:40 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
tengine[32732]: 2007/06/18_21:05:40 debug: run_graph: Transition 0: (Complete=3, Pending=0, Fired=1, Skipped=5, Incomplete=0)
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +         <lrm_resources>
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 info: run_graph: ====================================================
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummy1" type="Dummy" class="ocf" provider="heartbeat">
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 notice: run_graph: Transition 0: (Complete=4, Pending=0, Fired=0, Skipped=5, Incomplete=0)
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummy1_monitor_0" operation="monitor" crm-debug-origin="do_update_resource" transition_key="5:0:aa92046a-e910-4597-949a-6d64c8b5ec61" transition_magic="0:7;5:0:aa92046a-e910-4597-949a-6d64c8b5ec61" call_id="2" crm_feature_set="1.0.8" rc_code="7" op_status="0" interval="0" op_digest="c47037b095f8872488876d9dae9d7b2f"/>
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 debug: notify_crmd: Transition 0 status: te_abort - transient_attributes
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +           </lrm_resource>
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[32724]: 2007/06/18_21:05:40 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +       </lrm>
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:40 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:40 debug: send_peer_reply: Sending update diff 0.3.10 -> 0.3.11
crmd[32724]: 2007/06/18_21:05:40 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1182168340-21
pengine[32733]: 2007/06/18_21:05:40 debug: unpack_config: Default action timeout: 120s
pengine[32733]: 2007/06/18_21:05:40 debug: unpack_config: Default stickiness: 0
pengine[32733]: 2007/06/18_21:05:40 debug: unpack_config: Default failure stickiness: -1000000
pengine[32733]: 2007/06/18_21:05:40 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32733]: 2007/06/18_21:05:40 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32733]: 2007/06/18_21:05:40 notice: unpack_config: On loss of CCM Quorum: Ignore
crmd[32724]: 2007/06/18_21:05:40 debug: register_fsa_input_adv: route_message appended FSA input 33 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:05:40 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-1.bz2
pengine[32733]: 2007/06/18_21:05:40 info: determine_online_status: Node guest1 is online
crmd[32724]: 2007/06/18_21:05:40 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:40 info: unpack_graph: Unpacked transition 1: 5 actions in 5 synapses
pengine[32733]: 2007/06/18_21:05:40 info: determine_online_status: Node guest2 is online
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_LOG   
tengine[32732]: 2007/06/18_21:05:40 debug: initiate_action: Action 6: Increasing IDLE timer to 240000
pengine[32733]: 2007/06/18_21:05:40 info: group_print: Resource Group: grpDummy1
crmd[32724]: 2007/06/18_21:05:40 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:40 info: te_pseudo_action: Pseudo action 6 fired and confirmed
pengine[32733]: 2007/06/18_21:05:40 info: native_print:     prmDummy1	(heartbeat::ocf:Dummy):	Stopped 
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 info: send_rsc_command: Initiating action 4: prmDummy1_start_0 on guest2
pengine[32733]: 2007/06/18_21:05:40 debug: group_rsc_location: Processing rsc_location rulNode11 for grpDummy1
lrmd[32721]: 2007/06/18_21:05:40 debug: on_msg_perform_op: add an operation operation start[3] on ocf::Dummy::prmDummy1 for client 32724, its parameters: state=[/var/run/heartbeat/rsctmp/Dummy1.state] CRM_meta_id=[opDummy1Start] delay=[1] CRM_meta_timeout=[60000] CRM_meta_on_fail=[fence] crm_feature_set=[1.0.8] CRM_meta_name=[start]  to the operation list.
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 info: send_rsc_command: Initiating action 3: probe_complete on guest1
pengine[32733]: 2007/06/18_21:05:40 debug: group_rsc_location: Processing rsc_location rulNode12 for grpDummy1
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:40 debug: send_rsc_command: Skipping wait for 3
pengine[32733]: 2007/06/18_21:05:40 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy1
crmd[32724]: 2007/06/18_21:05:40 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[32732]: 2007/06/18_21:05:40 debug: run_graph: Transition 1: (Complete=0, Pending=0, Fired=3, Skipped=0, Incomplete=2)
pengine[32733]: 2007/06/18_21:05:40 debug: native_print: Allocating: prmDummy1	(heartbeat::ocf:Dummy):	Stopped 
crmd[32724]: 2007/06/18_21:05:40 debug: do_te_invoke: Starting a transition
tengine[32732]: 2007/06/18_21:05:40 debug: run_graph: Transition 1: (Complete=2, Pending=1, Fired=0, Skipped=0, Incomplete=2)
pengine[32733]: 2007/06/18_21:05:40 debug: native_assign_node: Color prmDummy1, Node[0] guest2: 200
crmd[32724]: 2007/06/18_21:05:40 info: do_lrm_rsc_op: Performing op=prmDummy1_start_0 key=4:1:aa92046a-e910-4597-949a-6d64c8b5ec61)
pengine[32733]: 2007/06/18_21:05:40 debug: native_assign_node: Color prmDummy1, Node[1] guest1: 100
pengine[32733]: 2007/06/18_21:05:40 debug: native_assign_node: Assigning guest2 to prmDummy1
pengine[32733]: 2007/06/18_21:05:40 notice: StartRsc:  guest2	Start prmDummy1
pengine[32733]: 2007/06/18_21:05:40 notice: RecurringOp: guest2	   prmDummy1_monitor_10000
pengine[32733]: 2007/06/18_21:05:40 info: process_pe_message: Transition 1: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-1.bz2
cib[32749]: 2007/06/18_21:05:40 info: write_cib_contents: Wrote version 0.3.11 of the CIB to disk (digest: 70a2611b9908f8113eefc244df4f4348)
lrmd[32721]: 2007/06/18_21:05:41 info: Exiting prmDummy1:start process 32748 returned rc 0.
crmd[32724]: 2007/06/18_21:05:41 info: process_lrm_event: LRM operation prmDummy1_start_0 (call=3, rc=0) complete 
crmd[32724]: 2007/06/18_21:05:41 info: build_operation_update: Digest for 0:0;4:1:aa92046a-e910-4597-949a-6d64c8b5ec61 (prmDummy1_start_0) was c47037b095f8872488876d9dae9d7b2f

crmd[32724]: 2007/06/18_21:05:41 info: log_data_element: build_operation_update: digest:source <parameters state="/var/run/heartbeat/rsctmp/Dummy1.state" delay="1"/>
crmd[32724]: 2007/06/18_21:05:41 debug: get_rsc_metadata: Retreiving metadata for Dummy::ocf:heartbeat
lrmd[32721]: 2007/06/18_21:05:41 debug: on_msg_perform_op: add an operation operation monitor[4] on ocf::Dummy::prmDummy1 for client 32724, its parameters: CRM_meta_interval=[10000] state=[/var/run/heartbeat/rsctmp/Dummy1.state] CRM_meta_id=[opDummy1Monitor] delay=[1] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[1.0.8] CRM_meta_name=[monitor]  to the operation list.
mgmtd[32725]: 2007/06/18_21:05:41 debug: update cib finished
crmd[32724]: 2007/06/18_21:05:41 debug: append_restart_list: Resource prmDummy1 does not support reloads
tengine[32732]: 2007/06/18_21:05:41 debug: te_update_diff: Processing diff (cib_update): 0.3.11 -> 0.3.12
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: - <cib num_updates="11"/>
crmd[32724]: 2007/06/18_21:05:41 debug: do_update_resource: Sent resource state update message: 37
tengine[32732]: 2007/06/18_21:05:41 info: match_graph_event: Action prmDummy1_start_0 (4) confirmed on 762a84bc-5633-4dcc-97ab-db3986cc778f
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: + <cib num_updates="12">
crmd[32724]: 2007/06/18_21:05:41 debug: process_lrm_event: Op prmDummy1_start_0 (call=3): confirmed
tengine[32732]: 2007/06/18_21:05:41 info: te_pseudo_action: Pseudo action 7 fired and confirmed
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:41 info: do_lrm_rsc_op: Performing op=prmDummy1_monitor_10000 key=5:1:aa92046a-e910-4597-949a-6d64c8b5ec61)
tengine[32732]: 2007/06/18_21:05:41 info: send_rsc_command: Initiating action 5: prmDummy1_monitor_10000 on guest2
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +     <node_state id="762a84bc-5633-4dcc-97ab-db3986cc778f">
crmd[32724]: 2007/06/18_21:05:41 debug: cancel_monitor: No previous invocation of prmDummy1_monitor_10000
tengine[32732]: 2007/06/18_21:05:41 debug: run_graph: Transition 1: (Complete=3, Pending=0, Fired=2, Skipped=0, Incomplete=0)
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +       <lrm id="762a84bc-5633-4dcc-97ab-db3986cc778f">
crmd[32724]: 2007/06/18_21:05:41 debug: cib_rsc_callback: Resource update 37 complete
tengine[32732]: 2007/06/18_21:05:41 debug: run_graph: Transition 1: (Complete=4, Pending=1, Fired=0, Skipped=0, Incomplete=0)
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +         <lrm_resources>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummy1">
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummy1_start_0" operation="start" crm-debug-origin="do_update_resource" transition_key="4:1:aa92046a-e910-4597-949a-6d64c8b5ec61" transition_magic="0:0;4:1:aa92046a-e910-4597-949a-6d64c8b5ec61" call_id="3" crm_feature_set="1.0.8" rc_code="0" op_status="0" interval="0" op_digest="c47037b095f8872488876d9dae9d7b2f"/>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +           </lrm_resource>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +         </lrm_resources>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +       </lrm>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:41 debug: send_peer_reply: Sending update diff 0.3.11 -> 0.3.12
cib[32759]: 2007/06/18_21:05:41 info: write_cib_contents: Wrote version 0.3.12 of the CIB to disk (digest: 8114457364f3a6240972cabe6291a4ef)
mgmtd[32725]: 2007/06/18_21:05:41 debug: update cib finished
tengine[32732]: 2007/06/18_21:05:41 debug: te_update_diff: Processing diff (cib_modify): 0.3.12 -> 0.3.13
tengine[32732]: 2007/06/18_21:05:41 info: extract_event: Aborting on transient_attributes changes for a2db98b0-fa70-4eff-990a-0f1ee9bc1430
tengine[32732]: 2007/06/18_21:05:41 info: update_abort_priority: Abort priority upgraded to 1000000
tengine[32732]: 2007/06/18_21:05:41 info: update_abort_priority: Abort action 0 superceeded by 2
tengine[32732]: 2007/06/18_21:05:41 debug: abort_transition_graph: extract_event:211 - Triggered graph processing : transient_attributes
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause <transient_attributes id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause   <instance_attributes id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause     <attributes>
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause       <nvpair id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430-probe_complete" name="probe_complete" value="true"/>
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause     </attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: - <cib num_updates="12"/>
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause   </instance_attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: + <cib num_updates="13">
tengine[32732]: 2007/06/18_21:05:41 debug: log_data_element: abort_transition_graph: Cause </transient_attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +   <status>
tengine[32732]: 2007/06/18_21:05:41 debug: run_graph: Transition 1: (Complete=4, Pending=1, Fired=0, Skipped=0, Incomplete=0)
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +     <node_state id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +       <transient_attributes id="a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +         <instance_attributes id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430">
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +           <attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +             <nvpair id="status-a2db98b0-fa70-4eff-990a-0f1ee9bc1430-probe_complete" name="probe_complete" value="true"/>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +           </attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +         </instance_attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +       </transient_attributes>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +     </node_state>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: +   </status>
cib[32720]: 2007/06/18_21:05:41 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:05:41 debug: send_peer_reply: Sending update diff 0.3.12 -> 0.3.13
cib[32763]: 2007/06/18_21:05:41 info: write_cib_contents: Wrote version 0.3.13 of the CIB to disk (digest: 66e76591c1ec93518a87a444c6a02f7b)
lrmd[32721]: 2007/06/18_21:05:42 info: Exiting prmDummy1:monitor process 32758 returned rc 0.
crmd[32724]: 2007/06/18_21:05:42 info: process_lrm_event: LRM operation prmDummy1_monitor_10000 (call=4, rc=0) complete 
crmd[32724]: 2007/06/18_21:05:42 debug: do_update_resource: Sent resource state update message: 38
mgmtd[32725]: 2007/06/18_21:05:42 debug: update cib finished
tengine[32732]: 2007/06/18_21:05:42 debug: te_update_diff: Processing diff (cib_update): 0.3.13 -> 0.3.14
tengine[32732]: 2007/06/18_21:05:42 info: match_graph_event: Action prmDummy1_monitor_10000 (5) confirmed on 762a84bc-5633-4dcc-97ab-db3986cc778f
tengine[32732]: 2007/06/18_21:05:42 debug: run_graph: ====================================================
tengine[32732]: 2007/06/18_21:05:42 info: run_graph: Transition 1: (Complete=5, Pending=0, Fired=0, Skipped=0, Incomplete=0)
tengine[32732]: 2007/06/18_21:05:42 debug: notify_crmd: Transition 1 status: te_abort - transient_attributes
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: - <cib num_updates="13"/>
crmd[32724]: 2007/06/18_21:05:42 debug: process_lrm_event: Op prmDummy1_monitor_10000 (call=4): confirmed
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: + <cib num_updates="14">
crmd[32724]: 2007/06/18_21:05:42 debug: handle_request: Transition cancelled: te_abort/transient_attributes
crmd[32724]: 2007/06/18_21:05:42 debug: register_fsa_input_adv: route_message appended FSA input 34 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:42 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:42 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:42 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
crmd[32724]: 2007/06/18_21:05:42 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +   <status>
crmd[32724]: 2007/06/18_21:05:42 debug: cib_rsc_callback: Resource update 38 complete
pengine[32733]: 2007/06/18_21:05:42 debug: unpack_config: Default action timeout: 120s
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +     <node_state id="762a84bc-5633-4dcc-97ab-db3986cc778f">
pengine[32733]: 2007/06/18_21:05:42 debug: unpack_config: Default stickiness: 0
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +       <lrm id="762a84bc-5633-4dcc-97ab-db3986cc778f">
pengine[32733]: 2007/06/18_21:05:42 debug: unpack_config: Default failure stickiness: -1000000
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +         <lrm_resources>
pengine[32733]: 2007/06/18_21:05:42 debug: unpack_config: STONITH of failed nodes is disabled
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +           <lrm_resource id="prmDummy1">
pengine[32733]: 2007/06/18_21:05:42 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +             <lrm_rsc_op id="prmDummy1_monitor_10000" operation="monitor" crm-debug-origin="do_update_resource" transition_key="5:1:aa92046a-e910-4597-949a-6d64c8b5ec61" transition_magic="0:0;5:1:aa92046a-e910-4597-949a-6d64c8b5ec61" call_id="4" crm_feature_set="1.0.8" rc_code="0" op_status="0" interval="10000" op_digest="c47037b095f8872488876d9dae9d7b2f"/>
pengine[32733]: 2007/06/18_21:05:42 notice: unpack_config: On loss of CCM Quorum: Ignore
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +           </lrm_resource>
pengine[32733]: 2007/06/18_21:05:42 info: determine_online_status: Node guest1 is online
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +         </lrm_resources>
crmd[32724]: 2007/06/18_21:05:42 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1182168342-23
pengine[32733]: 2007/06/18_21:05:42 info: determine_online_status: Node guest2 is online
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +       </lrm>
pengine[32733]: 2007/06/18_21:05:42 info: group_print: Resource Group: grpDummy1
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +     </node_state>
pengine[32733]: 2007/06/18_21:05:42 info: native_print:     prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: +   </status>
pengine[32733]: 2007/06/18_21:05:42 debug: group_rsc_location: Processing rsc_location rulNode11 for grpDummy1
cib[32720]: 2007/06/18_21:05:42 debug: log_data_element: cib:diff: + </cib>
pengine[32733]: 2007/06/18_21:05:42 debug: group_rsc_location: Processing rsc_location rulNode12 for grpDummy1
cib[32720]: 2007/06/18_21:05:42 debug: send_peer_reply: Sending update diff 0.3.13 -> 0.3.14
crmd[32724]: 2007/06/18_21:05:42 debug: register_fsa_input_adv: route_message appended FSA input 35 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:05:42 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-2.bz2
pengine[32733]: 2007/06/18_21:05:42 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy1
crmd[32724]: 2007/06/18_21:05:42 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:42 info: unpack_graph: Unpacked transition 2: 0 actions in 0 synapses
pengine[32733]: 2007/06/18_21:05:42 debug: native_print: Allocating: prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_LOG   
tengine[32732]: 2007/06/18_21:05:42 debug: print_graph: ## Empty transition graph ##
pengine[32733]: 2007/06/18_21:05:42 debug: native_assign_node: Color prmDummy1, Node[0] guest2: 200
crmd[32724]: 2007/06/18_21:05:42 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:05:42 debug: run_graph: ====================================================
pengine[32733]: 2007/06/18_21:05:42 debug: native_assign_node: Color prmDummy1, Node[1] guest1: 100
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:42 info: run_graph: Transition 2: (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0)
pengine[32733]: 2007/06/18_21:05:42 debug: native_assign_node: Assigning guest2 to prmDummy1
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:42 debug: print_graph: ## Empty transition graph ##
pengine[32733]: 2007/06/18_21:05:42 notice: NoRoleChange: Leave resource prmDummy1	(guest2)
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:05:42 info: notify_crmd: Transition 2 status: te_complete - <null>
pengine[32733]: 2007/06/18_21:05:42 info: process_pe_message: Transition 2: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-2.bz2
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[32732]: 2007/06/18_21:05:42 debug: print_graph: ## Empty transition graph ##
crmd[32724]: 2007/06/18_21:05:42 debug: do_te_invoke: Starting a transition
crmd[32724]: 2007/06/18_21:05:42 debug: handle_request: Transition complete: te_complete/(null)
crmd[32724]: 2007/06/18_21:05:42 debug: register_fsa_input_adv: route_message appended FSA input 36 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32724]: 2007/06/18_21:05:42 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:05:42 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:05:42 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32764]: 2007/06/18_21:05:42 info: write_cib_contents: Wrote version 0.3.14 of the CIB to disk (digest: f439243690d8707bcb8225028a48ed83)
lrmd[32721]: 2007/06/18_21:05:53 info: Exiting prmDummy1:monitor process 32765 returned rc 0.
lrmd[32721]: 2007/06/18_21:06:04 info: Exiting prmDummy1:monitor process 304 returned rc 0.
lrmd[32721]: 2007/06/18_21:06:15 info: Exiting prmDummy1:monitor process 308 returned rc 0.
tengine[32732]: 2007/06/18_21:06:18 debug: te_update_diff: Processing diff (cib_modify): 0.3.14 -> 0.3.15
crmd[32724]: 2007/06/18_21:06:18 debug: handle_request: Transition cancelled: te_abort/Non-status change
tengine[32732]: 2007/06/18_21:06:18 info: update_abort_priority: Abort priority upgraded to 1000000
crmd[32724]: 2007/06/18_21:06:18 debug: register_fsa_input_adv: route_message appended FSA input 37 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:06:18 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
crmd[32724]: 2007/06/18_21:06:18 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:06:18 debug: notify_crmd: Transition 2 status: te_abort - Non-status change
crmd[32724]: 2007/06/18_21:06:18 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:06:18 debug: print_graph: ## Empty transition graph ##
crmd[32724]: 2007/06/18_21:06:18 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
mgmtd[32725]: 2007/06/18_21:06:18 debug: update cib finished
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: - <cib num_updates="14"/>
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: + <cib num_updates="15">
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +   <configuration>
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +     <resources>
crmd[32724]: 2007/06/18_21:06:18 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +       <group id="grpDummy1">
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +         <primitive id="prmDummy1">
crmd[32724]: 2007/06/18_21:06:18 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1182168378-25
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +           <operations>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +             <op disabled="true" id="opDummy1Monitor"/>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +           </operations>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +         </primitive>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +       </group>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +     </resources>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: +   </configuration>
cib[32720]: 2007/06/18_21:06:18 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:06:18 debug: send_peer_reply: Sending update diff 0.3.14 -> 0.3.15
pengine[32733]: 2007/06/18_21:06:18 debug: unpack_config: Default action timeout: 120s
pengine[32733]: 2007/06/18_21:06:18 debug: unpack_config: Default stickiness: 0
pengine[32733]: 2007/06/18_21:06:18 debug: unpack_config: Default failure stickiness: -1000000
pengine[32733]: 2007/06/18_21:06:18 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32733]: 2007/06/18_21:06:18 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32733]: 2007/06/18_21:06:18 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32733]: 2007/06/18_21:06:18 info: determine_online_status: Node guest1 is online
pengine[32733]: 2007/06/18_21:06:18 info: determine_online_status: Node guest2 is online
pengine[32733]: 2007/06/18_21:06:18 info: group_print: Resource Group: grpDummy1
pengine[32733]: 2007/06/18_21:06:18 info: native_print:     prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
pengine[32733]: 2007/06/18_21:06:18 debug: group_rsc_location: Processing rsc_location rulNode11 for grpDummy1
pengine[32733]: 2007/06/18_21:06:18 debug: group_rsc_location: Processing rsc_location rulNode12 for grpDummy1
pengine[32733]: 2007/06/18_21:06:18 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy1
pengine[32733]: 2007/06/18_21:06:18 info: check_action_definition: Orphan action will be stopped: prmDummy1_monitor_10000 on guest2
pengine[32733]: 2007/06/18_21:06:18 debug: check_action_definition: Orphan action detected: prmDummy1_monitor_10000 on guest2
pengine[32733]: 2007/06/18_21:06:18 debug: native_print: Allocating: prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
pengine[32733]: 2007/06/18_21:06:18 debug: native_assign_node: Color prmDummy1, Node[0] guest2: 200
pengine[32733]: 2007/06/18_21:06:18 debug: native_assign_node: Color prmDummy1, Node[1] guest1: 100
pengine[32733]: 2007/06/18_21:06:18 debug: native_assign_node: Assigning guest2 to prmDummy1
pengine[32733]: 2007/06/18_21:06:18 notice: NoRoleChange: Leave resource prmDummy1	(guest2)
crmd[32724]: 2007/06/18_21:06:18 debug: register_fsa_input_adv: route_message appended FSA input 38 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32724]: 2007/06/18_21:06:18 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:06:18 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:06:18 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-3.bz2
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[32732]: 2007/06/18_21:06:18 info: unpack_graph: Unpacked transition 3: 1 actions in 1 synapses
crmd[32724]: 2007/06/18_21:06:18 debug: do_te_invoke: Starting a transition
tengine[32732]: 2007/06/18_21:06:18 debug: initiate_action: Action 5: Increasing IDLE timer to 240000
tengine[32732]: 2007/06/18_21:06:18 info: send_rsc_command: Initiating action 5: prmDummy1_cancel_10000 on guest2
tengine[32732]: 2007/06/18_21:06:18 debug: send_rsc_command: Action 5: Increasing transition 3 timeout to 300000 (2*120000 + 60000)
tengine[32732]: 2007/06/18_21:06:18 debug: run_graph: Transition 3: (Complete=0, Pending=0, Fired=1, Skipped=0, Incomplete=0)
lrmd[32721]: 2007/06/18_21:06:18 debug: cancel_op: operation monitor[4] on ocf::Dummy::prmDummy1 for client 32724, its parameters: CRM_meta_interval=[10000] CRM_meta_op_target_rc=[7] state=[/var/run/heartbeat/rsctmp/Dummy1.state] CRM_meta_id=[opDummy1Monitor] delay=[1] CRM_meta_timeout=[10000] CRM_meta_on_fail=[fence] crm_feature_set=[1.0.8] CRM_meta_name=[monitor]  cancelled
crmd[32724]: 2007/06/18_21:06:18 debug: cancel_monitor: Cancelling previous invocation of prmDummy1_monitor_10000 (4)
crmd[32724]: 2007/06/18_21:06:18 info: cancel_monitor: Couldn't cancel prmDummy1_monitor_10000 (4): -1
tengine[32732]: 2007/06/18_21:06:18 info: process_te_message: Processing (N)ACK lrm_invoke-lrmd-1182168378-27 from guest2
crmd[32724]: 2007/06/18_21:06:18 info: send_direct_ack: ACK'ing resource op prmDummy1_monitor_10000 from 5:3:aa92046a-e910-4597-949a-6d64c8b5ec61: lrm_invoke-lrmd-1182168378-27
tengine[32732]: 2007/06/18_21:06:18 info: match_graph_event: Action prmDummy1_monitor_10000 (5) confirmed on 762a84bc-5633-4dcc-97ab-db3986cc778f
tengine[32732]: 2007/06/18_21:06:18 debug: run_graph: ====================================================
tengine[32732]: 2007/06/18_21:06:18 info: run_graph: Transition 3: (Complete=1, Pending=0, Fired=0, Skipped=0, Incomplete=0)
tengine[32732]: 2007/06/18_21:06:18 info: notify_crmd: Transition 3 status: te_complete - <null>
crmd[32724]: 2007/06/18_21:06:18 debug: handle_request: Transition complete: te_complete/(null)
crmd[32724]: 2007/06/18_21:06:18 debug: register_fsa_input_adv: route_message appended FSA input 39 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
crmd[32724]: 2007/06/18_21:06:18 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_LOG   
crmd[32724]: 2007/06/18_21:06:18 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:06:18 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
pengine[32733]: 2007/06/18_21:06:18 info: process_pe_message: Transition 3: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-3.bz2
cib[312]: 2007/06/18_21:06:18 info: write_cib_contents: Wrote version 0.3.15 of the CIB to disk (digest: 9917c0333a2a241cc395465654893a20)
mgmtd[32725]: 2007/06/18_21:07:07 debug: update cib finished
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: - <cib num_updates="15">
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -   <configuration>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -     <resources>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -       <group id="grpDummy1">
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -         <primitive id="prmDummy1">
tengine[32732]: 2007/06/18_21:07:07 debug: te_update_diff: Processing diff (cib_modify): 0.3.15 -> 0.3.16
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -           <operations>
tengine[32732]: 2007/06/18_21:07:07 info: update_abort_priority: Abort priority upgraded to 1000000
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -             <op disabled="true" id="opDummy1Monitor"/>
tengine[32732]: 2007/06/18_21:07:07 debug: abort_transition_graph: te_update_diff:164 - Triggered graph processing : Non-status change
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -           </operations>
tengine[32732]: 2007/06/18_21:07:07 debug: notify_crmd: Transition 3 status: te_abort - Non-status change
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -         </primitive>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -       </group>
crmd[32724]: 2007/06/18_21:07:07 debug: handle_request: Transition cancelled: te_abort/Non-status change
crmd[32724]: 2007/06/18_21:07:07 debug: register_fsa_input_adv: route_message appended FSA input 40 (I_PE_CALC) (cause=C_IPC_MESSAGE) with data
crmd[32724]: 2007/06/18_21:07:07 debug: s_crmd_fsa: Processing I_PE_CALC: [ state=S_IDLE cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:07:07 info: do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC cause=C_IPC_MESSAGE origin=route_message ]
crmd[32724]: 2007/06/18_21:07:07 info: do_state_transition: All 2 cluster nodes are eligible to run resources.
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_PE_INVOKE
crmd[32724]: 2007/06/18_21:07:07 debug: do_pe_invoke: Requesting the current CIB: S_POLICY_ENGINE
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -     </resources>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: -   </configuration>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: - </cib>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: + <cib num_updates="16">
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +   <configuration>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +     <resources>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +       <group id="grpDummy1">
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +         <primitive id="prmDummy1">
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +           <operations>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +             <op disabled="false" id="opDummy1Monitor"/>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +           </operations>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +         </primitive>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +       </group>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +     </resources>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: +   </configuration>
cib[32720]: 2007/06/18_21:07:07 debug: log_data_element: cib:diff: + </cib>
cib[32720]: 2007/06/18_21:07:07 debug: send_peer_reply: Sending update diff 0.3.15 -> 0.3.16
crmd[32724]: 2007/06/18_21:07:07 debug: do_pe_invoke_callback: Invoking the PE: pe_calc-dc-1182168427-28
pengine[32733]: 2007/06/18_21:07:07 debug: unpack_config: Default action timeout: 120s
pengine[32733]: 2007/06/18_21:07:07 debug: unpack_config: Default stickiness: 0
pengine[32733]: 2007/06/18_21:07:07 debug: unpack_config: Default failure stickiness: -1000000
pengine[32733]: 2007/06/18_21:07:07 debug: unpack_config: STONITH of failed nodes is disabled
pengine[32733]: 2007/06/18_21:07:07 debug: unpack_config: Cluster is symmetric - resources can run anywhere by default
pengine[32733]: 2007/06/18_21:07:07 notice: unpack_config: On loss of CCM Quorum: Ignore
pengine[32733]: 2007/06/18_21:07:07 info: determine_online_status: Node guest1 is online
crmd[32724]: 2007/06/18_21:07:07 debug: register_fsa_input_adv: route_message appended FSA input 41 (I_PE_SUCCESS) (cause=C_IPC_MESSAGE) with data
pengine[32733]: 2007/06/18_21:07:07 info: determine_online_status: Node guest2 is online
crmd[32724]: 2007/06/18_21:07:07 debug: s_crmd_fsa: Processing I_PE_SUCCESS: [ state=S_POLICY_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
pengine[32733]: 2007/06/18_21:07:07 info: group_print: Resource Group: grpDummy1
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_LOG   
pengine[32733]: 2007/06/18_21:07:07 info: native_print:     prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
crmd[32724]: 2007/06/18_21:07:07 info: do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
pengine[32733]: 2007/06/18_21:07:07 debug: group_rsc_location: Processing rsc_location rulNode11 for grpDummy1
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
pengine[32733]: 2007/06/18_21:07:07 debug: group_rsc_location: Processing rsc_location rulNode12 for grpDummy1
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
pengine[32733]: 2007/06/18_21:07:07 debug: group_rsc_location: Processing rsc_location ping1:disconn:rule for grpDummy1
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
tengine[32732]: 2007/06/18_21:07:07 debug: process_te_message: Processing graph derived from /var/lib/heartbeat/pengine/pe-input-4.bz2
pengine[32733]: 2007/06/18_21:07:07 debug: native_print: Allocating: prmDummy1	(heartbeat::ocf:Dummy):	Started guest2
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_TE_INVOKE
tengine[32732]: 2007/06/18_21:07:07 info: unpack_graph: Unpacked transition 4: 0 actions in 0 synapses
pengine[32733]: 2007/06/18_21:07:07 debug: native_assign_node: Color prmDummy1, Node[0] guest2: 200
crmd[32724]: 2007/06/18_21:07:07 debug: do_te_invoke: Starting a transition
tengine[32732]: 2007/06/18_21:07:07 debug: print_graph: ## Empty transition graph ##
pengine[32733]: 2007/06/18_21:07:07 debug: native_assign_node: Color prmDummy1, Node[1] guest1: 100
crmd[32724]: 2007/06/18_21:07:07 debug: handle_request: Transition complete: te_complete/(null)
tengine[32732]: 2007/06/18_21:07:07 debug: run_graph: ====================================================
pengine[32733]: 2007/06/18_21:07:07 debug: native_assign_node: Assigning guest2 to prmDummy1
crmd[32724]: 2007/06/18_21:07:07 debug: register_fsa_input_adv: route_message appended FSA input 42 (I_TE_SUCCESS) (cause=C_IPC_MESSAGE) with data
tengine[32732]: 2007/06/18_21:07:07 info: run_graph: Transition 4: (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0)
pengine[32733]: 2007/06/18_21:07:07 notice: NoRoleChange: Leave resource prmDummy1	(guest2)
crmd[32724]: 2007/06/18_21:07:07 debug: s_crmd_fsa: Processing I_TE_SUCCESS: [ state=S_TRANSITION_ENGINE cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:07:07 debug: print_graph: ## Empty transition graph ##
pengine[32733]: 2007/06/18_21:07:07 info: process_pe_message: Transition 4: PEngine Input stored in: /var/lib/heartbeat/pengine/pe-input-4.bz2
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_LOG   
tengine[32732]: 2007/06/18_21:07:07 info: notify_crmd: Transition 4 status: te_complete - <null>
crmd[32724]: 2007/06/18_21:07:07 info: do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS cause=C_IPC_MESSAGE origin=route_message ]
tengine[32732]: 2007/06/18_21:07:07 debug: print_graph: ## Empty transition graph ##
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_DC_TIMER_STOP
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_INTEGRATE_TIMER_STOP
crmd[32724]: 2007/06/18_21:07:07 debug: do_fsa_action: actions:trace: 	// A_FINALIZE_TIMER_STOP
cib[318]: 2007/06/18_21:07:07 info: write_cib_contents: Wrote version 0.3.16 of the CIB to disk (digest: c61988c808a59d90c23a23db0ddfc90e)
