[Linux-HA] HA restarts unexpected after machine reboot

Michael Liebl ml at 2007.antispam.de
Thu Sep 13 04:58:55 MDT 2007


Hello!

Sorry, I have to ask again, because the Problem still exists.

My 2 node Linux-HA active/passive cluster works not as I expect.

Node1 is active and owns all resources (just one additional IP).
I reboot Node2 and HA is startet automatically by init on Node2,
HA runs with active resources on Node1.
Fine so far.

40 seconds after HA was started on Node2, HA ist "automagically"
restartet on Node1 and Node2.

Why? What is going wrong here?
Misconfigured?

Also suspicious: 
# netstat -tulpn
Active Internet connections (only servers)
udp 0.0.0.0:694	0.0.0.0:* 4164/heartbeat: hea
udp 0.0.0.0:694 0.0.0.0:* 4164/heartbeat: hea 

Why 2 times same port?!

I'm using Ubuntu/dapper with Heartbeat v1.2.4.
There are no iptables or something like this.
If anyone needs more logs or something, just say.



Node1:
Aug 29 16:17:27 Node1 heartbeat[4164]: WARN: node Node2: is dead
Aug 29 16:17:27 Node1 heartbeat[4164]: info: Dead node Node2 gave up resources.
Aug 29 16:17:27 Node1 heartbeat[4164]: debug: hb_rsc_recover_dead_resources: other now stable
Aug 29 16:17:27 Node1 heartbeat[4164]: info: Link Node2:eth0 dead.
Aug 29 16:18:49 Node1 heartbeat[4164]: info: Heartbeat restart on node Node2
Aug 29 16:18:49 Node1 heartbeat[4164]: info: Link Node2:eth0 up.
Aug 29 16:18:49 Node1 heartbeat[4164]: info: Status update for node Node2: status up
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: Status seqno: 1 msgtime: 1188397128
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: Process [status] started pid 11538
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: Starting notify process [status]
Aug 29 16:18:49 Node1 heartbeat[11538]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:18:49 Node1 heartbeat[11538]: debug: notify_world: Running harc status
Aug 29 16:18:49 Node1 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:18:49 Node1 heartbeat[4164]: info: Exiting status process 11538 returned rc 0.
Aug 29 16:18:49 Node1 heartbeat[4164]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:18:51 Node1 heartbeat[4164]: info: Status update for node Node2: status active
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Status seqno: 3 msgtime: 1188397130
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Process [status] started pid 11542
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Starting notify process [status]
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: process_resources: other now unstable
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Sending hold resources msg: all, stable=1 # <none>
Aug 29 16:18:51 Node1 heartbeat[4164]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node1 heartbeat[11542]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:18:51 Node1 heartbeat[11542]: debug: notify_world: Running harc status
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: process_resources(2):  other now unstable
Aug 29 16:18:51 Node1 heartbeat[4164]: info: other_holds_resources: 0
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node1 heartbeat[4164]: info: remote resource transition completed.
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Sending hold resources msg: all, stable=1 # <none>
Aug 29 16:18:51 Node1 heartbeat[4164]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: Calling PerformAutoFailback()
Aug 29 16:18:51 Node1 heartbeat[4164]: info: other_holds_resources: 0
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node1 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:18:51 Node1 heartbeat[4164]: info: Exiting status process 11542 returned rc 0.
Aug 29 16:18:51 Node1 heartbeat[4164]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Daily informational memory statistics
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 995/216309 ms age 2770 [pid4164/MST_CONTROL]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 24024/5840463  1650420/771198 [pid4164/MST_CONTROL]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 1657396 total malloc bytes. pid [4164/MST_CONTROL]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 2048000
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 0/5 ms age 275050 [pid4170/HBFIFO]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 0/82  252/0 [pid4170/HBFIFO]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 1468 total malloc bytes. pid [4170/HBFIFO]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 135168
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 0/0 ms age 626108100 [pid4171/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 0/0  0/0 [pid4171/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 0 total malloc bytes. pid [4171/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 0
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 0/0 ms age 626108100 [pid4172/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 0/0  0/0 [pid4172/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 0 total malloc bytes. pid [4172/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 0
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 0/0 ms age 626108100 [pid4173/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 0/0  0/0 [pid4173/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 0 total malloc bytes. pid [4173/HBWRITE]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 0
Aug 29 16:21:41 Node1 heartbeat[4164]: info: MSG stats: 0/0 ms age 626108100 [pid4174/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: ha_malloc stats: 0/216282  14/0 [pid4174/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: RealMalloc stats: 270 total malloc bytes. pid [4174/HBREAD]
Aug 29 16:21:41 Node1 heartbeat[4164]: info: Current arena value: 135168
Aug 29 16:21:41 Node1 heartbeat[4164]: info: These are nothing to worry about.
Aug 29 16:22:06 Node1 heartbeat[4164]: info: other_holds_resources: 3
Aug 29 16:22:06 Node1 heartbeat[4164]: ERROR: Both machines own our resources!
Aug 29 16:22:06 Node1 heartbeat[4164]: ERROR: Both machines own foreign resources!
Aug 29 16:22:06 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node1 heartbeat[4164]: info: other_holds_resources: 3
Aug 29 16:22:06 Node1 heartbeat[4164]: ERROR: Both machines own our resources!
Aug 29 16:22:06 Node1 heartbeat[4164]: ERROR: Both machines own foreign resources!
Aug 29 16:22:06 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node1 heartbeat[4164]: debug: process_resources(2):  other now unstable
Aug 29 16:22:06 Node1 heartbeat[4164]: info: other_holds_resources: 0
Aug 29 16:22:06 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: process_resources(4):  other now stable - T_SHUTDONE
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:07 Node1 heartbeat[4164]: info: Received shutdown notice from 'Node2'.
Aug 29 16:22:07 Node1 heartbeat[4164]: info: Resources being acquired from Node2.
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: Process [status] started pid 11548
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: Starting notify process [status]
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: takeover_from_node: other now stable
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: Process [req_our_resources(ask)] started pid 11549
Aug 29 16:22:07 Node1 heartbeat[11548]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:22:07 Node1 heartbeat[11548]: debug: notify_world: Running harc status
Aug 29 16:22:07 Node1 heartbeat[11549]: debug: req_our_resources(/usr/lib/heartbeat/ResourceManager listkeys Node1)
Aug 29 16:22:07 Node1 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:22:07 Node1 heartbeat[11549]: debug: req_our_resources(): running [/usr/lib/heartbeat/req_resource IPaddr2::192.168.8.150/24/eth0:fs]
Aug 29 16:22:07 Node1 heartbeat: info: /usr/lib/heartbeat/mach_down: nice_failback: foreign resources acquired
Aug 29 16:22:07 Node1 heartbeat[4164]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:22:07 Node1 heartbeat[4164]: info: mach_down takeover complete.
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: process_resources(3):  other now stable
Aug 29 16:22:07 Node1 heartbeat[4164]: info: AnnounceTakeover(local 1, foreign 1, reason 'mach_down' (1))
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 2, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:07 Node1 heartbeat: info: mach_down takeover complete for node Node2.
Aug 29 16:22:07 Node1 heartbeat[4164]: info: Exiting status process 11548 returned rc 0.
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: StartNextRemoteRscReq(): child count 1
Aug 29 16:22:07 Node1 heartbeat[11549]: info: 1 local resources from [/usr/lib/heartbeat/ResourceManager listkeys Node1]
Aug 29 16:22:07 Node1 heartbeat[11549]: info: Local Resource acquisition completed.
Aug 29 16:22:07 Node1 heartbeat[11549]: debug: Sending hold resources msg: all, stable=1 # req_our_resources()
Aug 29 16:22:07 Node1 heartbeat[4164]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:07 Node1 heartbeat[4164]: info: Exiting req_our_resources(ask) process 11549 returned rc 0.
Aug 29 16:22:07 Node1 heartbeat[4164]: debug: RscMgmtProc 'req_our_resources(ask)' exited code 0
Aug 29 16:22:26 Node1 heartbeat[4164]: WARN: node Node2: is dead
Aug 29 16:22:26 Node1 heartbeat[4164]: info: Dead node Node2 gave up resources.
Aug 29 16:22:26 Node1 heartbeat[4164]: debug: hb_rsc_recover_dead_resources: other now stable
Aug 29 16:22:31 Node1 heartbeat[4164]: info: Link Node2:eth0 dead.
Aug 29 16:22:46 Node1 heartbeat[4164]: WARN: Cluster node Node2 returning after partition.
Aug 29 16:22:46 Node1 heartbeat[4164]: WARN: Deadtime value may be too small.
Aug 29 16:22:46 Node1 heartbeat[4164]: info: See documentation for information on tuning deadtime.
Aug 29 16:22:46 Node1 heartbeat[4164]: info: Link Node2:eth0 up.
Aug 29 16:22:46 Node1 heartbeat[4164]: WARN: Late heartbeat: Node Node2: interval 39400 ms
Aug 29 16:22:46 Node1 heartbeat[4164]: info: Status update for node Node2: status active
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: Status seqno: 53 msgtime: 1188397365
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: Process [status] started pid 11617
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: Starting notify process [status]
Aug 29 16:22:46 Node1 heartbeat[11617]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:22:46 Node1 heartbeat[11617]: debug: notify_world: Running harc status
Aug 29 16:22:46 Node1 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:22:46 Node1 heartbeat[4164]: info: Exiting status process 11617 returned rc 0.
Aug 29 16:22:46 Node1 heartbeat[4164]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:48 Node1 heartbeat[4164]: info: hb_giveup_resources(): current status: active
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: Sending hold resources msg: none, stable=0 # shutdown
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:48 Node1 heartbeat[4164]: info: Heartbeat shutdown in progress. (4164)
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: Process [hb_giveup_resources] started pid 11621
Aug 29 16:22:48 Node1 heartbeat[11621]: info: Giving up all HA resources.
Aug 29 16:22:48 Node1 heartbeat: info: Releasing resource group: Node1 IPaddr2::192.168.8.150/24/eth0:fs
Aug 29 16:22:48 Node1 heartbeat: info: Running /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop
Aug 29 16:22:48 Node1 heartbeat: debug: Starting /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop
Aug 29 16:22:48 Node1 heartbeat: info: /sbin/ip -f inet addr delete 192.168.8.150 dev eth0
Aug 29 16:22:48 Node1 heartbeat: info: /sbin/ip -o -f inet addr show eth0
Aug 29 16:22:48 Node1 heartbeat: info: IP Address 192.168.8.150 released
Aug 29 16:22:48 Node1 heartbeat: debug: /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop done. RC=0
Aug 29 16:22:48 Node1 heartbeat[11621]: info: All HA resources relinquished.
Aug 29 16:22:48 Node1 heartbeat[11621]: debug: Sending T_SHUTDONE.
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: Received T_SHUTDONE from us.
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: Calling hb_mcp_final_shutdown in a second.
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: RscMgmtProc 'hb_giveup_resources' exited code 0
Aug 29 16:22:48 Node1 heartbeat[4164]: debug: hb_mcp_final_shutdown() phase 0
Aug 29 16:22:49 Node1 heartbeat[4164]: debug: hb_mcp_final_shutdown() phase 1
Aug 29 16:22:49 Node1 heartbeat[4164]: info: killing HBFIFO process 4170 with signal 15
Aug 29 16:22:49 Node1 heartbeat[4164]: info: killing HBWRITE process 4171 with signal 15
Aug 29 16:22:49 Node1 heartbeat[4164]: info: killing HBREAD process 4172 with signal 15
Aug 29 16:22:49 Node1 heartbeat[4164]: info: killing HBWRITE process 4173 with signal 15
Aug 29 16:22:49 Node1 heartbeat[4164]: info: killing HBREAD process 4174 with signal 15
Aug 29 16:22:49 Node1 heartbeat[4170]: debug: Process 4170 processing SIGTERM
Aug 29 16:22:49 Node1 heartbeat[4170]: debug: Exiting from pid 4170 [rc=15]
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Core process 4170 exited. 5 remaining
Aug 29 16:22:49 Node1 heartbeat[4171]: debug: Process 4171 processing SIGTERM
Aug 29 16:22:49 Node1 heartbeat[4171]: debug: Exiting from pid 4171 [rc=15]
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Core process 4171 exited. 4 remaining
Aug 29 16:22:49 Node1 heartbeat[4172]: debug: Process 4172 processing SIGTERM
Aug 29 16:22:49 Node1 heartbeat[4172]: debug: Exiting from pid 4172 [rc=15]
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Core process 4172 exited. 3 remaining
Aug 29 16:22:49 Node1 heartbeat[4173]: debug: Process 4173 processing SIGTERM
Aug 29 16:22:49 Node1 heartbeat[4173]: debug: Exiting from pid 4173 [rc=15]
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Core process 4173 exited. 2 remaining
Aug 29 16:22:49 Node1 heartbeat[4174]: debug: Process 4174 processing SIGTERM
Aug 29 16:22:49 Node1 heartbeat[4174]: debug: Exiting from pid 4174 [rc=15]
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Core process 4174 exited. 1 remaining
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Heartbeat shutdown complete.
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Heartbeat restart triggered.
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Restarting heartbeat.
Aug 29 16:22:49 Node1 heartbeat[4164]: info: Performing heartbeat restart exec.
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(keepalive,5)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(warntime,10)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(deadtime,20)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(initdead,40)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(auto_failback,off)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(udpport,694)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(node,Node1)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(node,Node2)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Beginning authentication parsing
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: 16 max authentication methods
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Keyfile opened
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Keyfile perms OK
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: 16 max authentication methods
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Found authentication method [md5]
Aug 29 16:23:10 Node1 heartbeat[4164]: info: AUTH: i=1: key = 0x80d92fc, auth=0xb7e3b46c, authname=md5
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Outbound signing method is 1
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: Authentication parsing complete [1]
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(hopfudge,1)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(baud,19200)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(hbgenmethod,file)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(realtime,true)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(normalpoll,true)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(msgfmt,classic)
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: add_option(log_badpack,true)
Aug 29 16:23:10 Node1 heartbeat[4164]: info: **************************
Aug 29 16:23:10 Node1 heartbeat[4164]: info: Configuration validated. Starting heartbeat 1.2.4
Aug 29 16:23:10 Node1 heartbeat[4164]: debug: HA configuration OK.  Heartbeat starting.
Aug 29 16:23:10 Node1 heartbeat[11704]: info: heartbeat: version 1.2.4
Aug 29 16:23:10 Node1 heartbeat[11704]: info: Heartbeat generation: 37
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: bound send socket to device: eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: bound receive socket to device: eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: started on port 694 interface eth0 to 192.168.8.151
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: ucast channel eth0 now open...
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: bound send socket to device: eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: bound receive socket to device: eth0
Aug 29 16:23:10 Node1 heartbeat[11704]: info: ucast: started on port 694 interface eth0 to 192.168.8.152
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: ucast channel eth0 now open...
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: FIFO process pid: 11710
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: write process pid: 11711
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: read child process pid: 11712
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: write process pid: 11713
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: read child process pid: 11714
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: Limiting CPU: 30 CPU seconds every 60000 milliseconds
Aug 29 16:23:10 Node1 heartbeat[11704]: info: pid 11704 locked in memory.
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: Waiting for child processes to start
Aug 29 16:23:10 Node1 heartbeat[11704]: info: Local status now set to: 'up'
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: All your child process are belong to us
Aug 29 16:23:10 Node1 heartbeat[11704]: debug: Starting local status message @ 5000 ms intervals
Aug 29 16:23:11 Node1 heartbeat[11710]: info: pid 11710 locked in memory.
Aug 29 16:23:11 Node1 heartbeat[11710]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node1 heartbeat[11711]: info: pid 11711 locked in memory.
Aug 29 16:23:11 Node1 heartbeat[11711]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node1 heartbeat[11712]: info: pid 11712 locked in memory.
Aug 29 16:23:11 Node1 heartbeat[11712]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node1 heartbeat[11713]: info: pid 11713 locked in memory.
Aug 29 16:23:11 Node1 heartbeat[11713]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node1 heartbeat[11714]: info: pid 11714 locked in memory.
Aug 29 16:23:11 Node1 heartbeat[11714]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node1 heartbeat[11704]: info: Link Node2:eth0 up.
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: CreateInitialFilter: ip-request-resp
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: CreateInitialFilter: ask_resources
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: CreateInitialFilter: status
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: CreateInitialFilter: hb_takeover
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: CreateInitialFilter: ip-request
Aug 29 16:23:11 Node1 heartbeat[11704]: info: Status update for node Node2: status active
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Status seqno: 3 msgtime: 1188397391
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: notify_world: invoking harc: OLD status: up
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Process [status] started pid 11715
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Starting notify process [status]
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Comm_now_up(): updating status to active
Aug 29 16:23:11 Node1 heartbeat[11704]: info: Local status now set to: 'active'
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Sending local starting msg: resourcestate = 0
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 0
Aug 29 16:23:11 Node1 heartbeat[11704]: info: AnnounceTakeover(local 0, foreign 1, reason 'HB_R_BOTHSTARTING' (0))
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: process_resources: other now unstable
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: Sending hold resources msg: none, stable=0 # <none>
Aug 29 16:23:11 Node1 heartbeat[11704]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:23:11 Node1 heartbeat[11704]: info: STATE 1 => 3
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:23:11 Node1 heartbeat[11704]: info: STATE 3 => 2
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 2
Aug 29 16:23:11 Node1 heartbeat[11715]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:23:11 Node1 heartbeat[11715]: debug: notify_world: Running harc status
Aug 29 16:23:11 Node1 heartbeat[11704]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: process_resources(2):  other now unstable
Aug 29 16:23:11 Node1 heartbeat[11704]: info: other_holds_resources: 0
Aug 29 16:23:11 Node1 heartbeat[11704]: info: STATE 2 => 3
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:23:11 Node1 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:23:11 Node1 heartbeat[11704]: info: Exiting status process 11715 returned rc 0.
Aug 29 16:23:11 Node1 heartbeat[11704]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: Process [req_our_resources(ask)] started pid 11719
Aug 29 16:23:23 Node1 heartbeat[11704]: info: local resource transition completed.
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: Sending hold resources msg: local, stable=1 # <none>
Aug 29 16:23:23 Node1 heartbeat[11704]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (0))
Aug 29 16:23:23 Node1 heartbeat[11704]: info: Initial resource acquisition complete (T_RESOURCES(us))
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11704]: info: remote resource transition completed.
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: Sending hold resources msg: local, stable=1 # <none>
Aug 29 16:23:23 Node1 heartbeat[11704]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: Calling PerformAutoFailback()
Aug 29 16:23:23 Node1 heartbeat[11704]: info: other_holds_resources: 1
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11704]: info: other_holds_resources: 1
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11719]: debug: req_our_resources(/usr/lib/heartbeat/ResourceManager listkeys Node1)
Aug 29 16:23:23 Node1 heartbeat[11704]: info: other_holds_resources: 1
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node1 heartbeat[11719]: debug: req_our_resources(): running [/usr/lib/heartbeat/req_resource IPaddr2::192.168.8.150/24/eth0:fs]
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: StartNextRemoteRscReq(): child count 1
Aug 29 16:23:23 Node1 heartbeat[11719]: info: 1 local resources from [/usr/lib/heartbeat/ResourceManager listkeys Node1]
Aug 29 16:23:23 Node1 heartbeat[11719]: info: Local Resource acquisition completed.
Aug 29 16:23:23 Node1 heartbeat[11719]: debug: Sending hold resources msg: local, stable=1 # req_our_resources()
Aug 29 16:23:23 Node1 heartbeat[11704]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:23:23 Node1 heartbeat[11704]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:25 Node1 heartbeat[11704]: info: Exiting req_our_resources(ask) process 11719 returned rc 0.
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: RscMgmtProc 'req_our_resources(ask)' exited code 0
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: Process [ip-request-resp] started pid 11767
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: Starting notify process [ip-request-resp]
Aug 29 16:23:25 Node1 heartbeat[11767]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:23:25 Node1 heartbeat[11767]: debug: notify_world: Running harc ip-request-resp
Aug 29 16:23:25 Node1 heartbeat: info: Running /etc/ha.d/rc.d/ip-request-resp ip-request-resp
Aug 29 16:23:25 Node1 heartbeat: received ip-request-resp IPaddr2::192.168.8.150/24/eth0:fs OK yes
Aug 29 16:23:25 Node1 heartbeat: info: Acquiring resource group: Node1 IPaddr2::192.168.8.150/24/eth0:fs
Aug 29 16:23:25 Node1 heartbeat: info: Running /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start
Aug 29 16:23:25 Node1 heartbeat: debug: Starting /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start
Aug 29 16:23:25 Node1 heartbeat: info: /sbin/ip -f inet addr add 192.168.8.150/24 brd 192.168.8.255 dev eth0 label eth0:fs
Aug 29 16:23:25 Node1 heartbeat: info: /sbin/ip link set eth0 up
Aug 29 16:23:25 Node1 heartbeat: /usr/lib/heartbeat/send_arp -i 200 -r 5 -p /var/lib/heartbeat/rsctmp/send_arp/send_arp-192.168.8.150 eth0 192.168.8.150 auto 192.168.8.150 ffffffffffff
Aug 29 16:23:25 Node1 heartbeat: debug: /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start done. RC=0
Aug 29 16:23:25 Node1 heartbeat[11704]: info: Exiting ip-request-resp process 11767 returned rc 0.
Aug 29 16:23:25 Node1 heartbeat[11704]: debug: RscMgmtProc 'ip-request-resp' exited code 0
Aug 29 16:23:25 Node1 heartbeat[11704]: info: AnnounceTakeover(local 1, foreign 1, reason 'ip-request-resp' (1))




Node2:
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(keepalive,5)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(warntime,10)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(deadtime,20)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(initdead,40)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(auto_failback,off)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(udpport,694)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(node,Node1)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(node,Node2)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Beginning authentication parsing
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: 16 max authentication methods
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Keyfile opened
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Keyfile perms OK
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: 16 max authentication methods
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Found authentication method [md5]
Aug 29 16:18:47 Node2 heartbeat[4097]: info: AUTH: i=1: key = 0x80d8cfc, auth=0xb7d7e46c, authname=md5
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Outbound signing method is 1
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: Authentication parsing complete [1]
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(hopfudge,1)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(baud,19200)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(hbgenmethod,file)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(realtime,true)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(normalpoll,true)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(msgfmt,classic)
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: add_option(log_badpack,true)
Aug 29 16:18:47 Node2 heartbeat[4097]: info: **************************
Aug 29 16:18:47 Node2 heartbeat[4097]: info: Configuration validated. Starting heartbeat 1.2.4
Aug 29 16:18:47 Node2 heartbeat[4097]: debug: HA configuration OK.  Heartbeat starting.
Aug 29 16:18:47 Node2 heartbeat[4098]: info: heartbeat: version 1.2.4
Aug 29 16:18:47 Node2 heartbeat[4098]: info: Heartbeat generation: 30
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: bound send socket to device: eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: bound receive socket to device: eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: started on port 694 interface eth0 to 192.168.8.151
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: ucast channel eth0 now open...
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: bound send socket to device: eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: bound receive socket to device: eth0
Aug 29 16:18:48 Node2 heartbeat[4098]: info: ucast: started on port 694 interface eth0 to 192.168.8.152
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: ucast channel eth0 now open...
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: FIFO process pid: 4174
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: write process pid: 4175
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: read child process pid: 4176
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: write process pid: 4177
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: read child process pid: 4178
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: Limiting CPU: 30 CPU seconds every 60000 milliseconds
Aug 29 16:18:48 Node2 heartbeat[4098]: info: pid 4098 locked in memory.
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: Waiting for child processes to start
Aug 29 16:18:48 Node2 heartbeat[4098]: info: Local status now set to: 'up'
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: All your child process are belong to us
Aug 29 16:18:48 Node2 heartbeat[4098]: debug: Starting local status message @ 5000 ms intervals
Aug 29 16:18:49 Node2 heartbeat[4174]: info: pid 4174 locked in memory.
Aug 29 16:18:49 Node2 heartbeat[4174]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:18:49 Node2 heartbeat[4175]: info: pid 4175 locked in memory.
Aug 29 16:18:49 Node2 heartbeat[4175]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:18:49 Node2 heartbeat[4176]: info: pid 4176 locked in memory.
Aug 29 16:18:49 Node2 heartbeat[4176]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:18:49 Node2 heartbeat[4177]: info: pid 4177 locked in memory.
Aug 29 16:18:49 Node2 heartbeat[4178]: info: pid 4178 locked in memory.
Aug 29 16:18:49 Node2 heartbeat[4177]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:18:49 Node2 heartbeat[4178]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:18:50 Node2 heartbeat[4098]: info: Link Node1:eth0 up.
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: CreateInitialFilter: ip-request-resp
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: CreateInitialFilter: ask_resources
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: CreateInitialFilter: status
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: CreateInitialFilter: hb_takeover
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: CreateInitialFilter: ip-request
Aug 29 16:18:50 Node2 heartbeat[4098]: info: Status update for node Node1: status active
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Status seqno: 108125 msgtime: 1188397131
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: notify_world: invoking harc: OLD status: up
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Process [status] started pid 4494
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Starting notify process [status]
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Comm_now_up(): updating status to active
Aug 29 16:18:50 Node2 heartbeat[4098]: info: Local status now set to: 'active'
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Sending local starting msg: resourcestate = 0
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 0
Aug 29 16:18:50 Node2 heartbeat[4494]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:18:50 Node2 heartbeat[4494]: debug: notify_world: Running harc status
Aug 29 16:18:50 Node2 heartbeat[4098]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:18:50 Node2 heartbeat[4098]: info: remote resource transition completed.
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Sending hold resources msg: none, stable=0 # <none>
Aug 29 16:18:50 Node2 heartbeat[4098]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:18:50 Node2 heartbeat[4098]: info: STATE 1 => 3
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Calling PerformAutoFailback()
Aug 29 16:18:50 Node2 heartbeat[4098]: info: other_holds_resources: 3
Aug 29 16:18:50 Node2 heartbeat[4098]: info: remote resource transition completed.
Aug 29 16:18:50 Node2 heartbeat[4098]: info: Local Resource acquisition completed. (none)
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Sending hold resources msg: none, stable=1 # <none>
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: Calling PerformAutoFailback()
Aug 29 16:18:50 Node2 heartbeat[4098]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(them)' (0))
Aug 29 16:18:50 Node2 heartbeat[4098]: info: Initial resource acquisition complete (T_RESOURCES(them))
Aug 29 16:18:50 Node2 heartbeat[4098]: info: STATE 3 => 4
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:50 Node2 heartbeat[4098]: info: other_holds_resources: 3
Aug 29 16:18:50 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:18:51 Node2 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:18:51 Node2 heartbeat[4098]: info: Exiting status process 4494 returned rc 0.
Aug 29 16:18:51 Node2 heartbeat[4098]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:19:18 Node2 ntpd[3870]: adjusting local clock by 0.474626s
Aug 29 16:20:21 Node2 ntpd[3870]: adjusting local clock by 0.475713s
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: node Node1: is dead
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: No STONITH device configured.
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Shared disks are not protected.
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Resources being acquired from Node1.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Process [status] started pid 4500
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Starting notify process [status]
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: takeover_from_node: other now stable
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Process [req_our_resources] started pid 4501
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: node Node2: is dead
Aug 29 16:22:06 Node2 heartbeat[4098]: ERROR: No local heartbeat. Forcing restart.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 2, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Shutdown delayed until current resource activity finishes.
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Link Node1:eth0 dead.
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Late heartbeat: Node Node2: interval 42250 ms
Aug 29 16:22:06 Node2 heartbeat[4500]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:22:06 Node2 heartbeat[4500]: debug: notify_world: Running harc status
Aug 29 16:22:06 Node2 heartbeat[4501]: debug: req_our_resources(/usr/lib/heartbeat/ResourceManager listkeys Node2)
Aug 29 16:22:06 Node2 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:22:06 Node2 heartbeat[4501]: info: No local resources [/usr/lib/heartbeat/ResourceManager listkeys Node2] to acquire.
Aug 29 16:22:06 Node2 heartbeat[4501]: debug: Sending hold resources msg: all, stable=1 # req_our_resources()
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 2, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 2, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 2, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Exiting req_our_resources process 4501 returned rc 0.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: RscMgmtProc 'req_our_resources' exited code 0
Aug 29 16:22:06 Node2 heartbeat[4098]: info: AnnounceTakeover(local 1, foreign 1, reason 'req_our_resources' (1))
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: StartNextRemoteRscReq(): child count 1
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Cluster node Node1 returning after partition.
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Deadtime value may be too small.
Aug 29 16:22:06 Node2 heartbeat[4098]: info: See documentation for information on tuning deadtime.
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Link Node1:eth0 up.
Aug 29 16:22:06 Node2 heartbeat[4098]: WARN: Late heartbeat: Node Node1: interval 44400 ms
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Status update for node Node1: status active
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Status seqno: 108166 msgtime: 1188397326
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: StartNextRemoteRscReq(): child count 1
Aug 29 16:22:06 Node2 heartbeat: info: Taking over resource group IPaddr2::192.168.8.150/24/eth0:fs
Aug 29 16:22:06 Node2 heartbeat: info: Acquiring resource group: Node1 IPaddr2::192.168.8.150/24/eth0:fs
Aug 29 16:22:06 Node2 heartbeat: info: Running /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start
Aug 29 16:22:06 Node2 heartbeat: debug: Starting /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start
Aug 29 16:22:06 Node2 heartbeat: info: /sbin/ip -f inet addr add 192.168.8.150/24 brd 192.168.8.255 dev eth0 label eth0:fs
Aug 29 16:22:06 Node2 heartbeat: info: /sbin/ip link set eth0 up
Aug 29 16:22:06 Node2 heartbeat: /usr/lib/heartbeat/send_arp -i 200 -r 5 -p /var/lib/heartbeat/rsctmp/send_arp/send_arp-192.168.8.150 eth0 192.168.8.150 auto 192.168.8.150 ffffffffffff
Aug 29 16:22:06 Node2 heartbeat: debug: /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs start done. RC=0
Aug 29 16:22:06 Node2 heartbeat: info: /usr/lib/heartbeat/mach_down: nice_failback: foreign resources acquired
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 1, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:22:06 Node2 heartbeat[4098]: info: mach_down takeover complete.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: process_resources(3):  other now stable
Aug 29 16:22:06 Node2 heartbeat[4098]: info: AnnounceTakeover(local 1, foreign 1, reason 'mach_down' (1))
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat: info: mach_down takeover complete for node Node1.
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Exiting status process 4500 returned rc 0.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Process [status] started pid 4640
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Starting notify process [status]
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4640]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:22:06 Node2 heartbeat[4640]: debug: notify_world: Running harc status
Aug 29 16:22:06 Node2 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Exiting status process 4640 returned rc 0.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:22:06 Node2 heartbeat[4098]: info: hb_giveup_resources(): current status: active
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Sending hold resources msg: none, stable=0 # shutdown
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:06 Node2 heartbeat[4098]: info: Heartbeat shutdown in progress. (4098)
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Process [hb_giveup_resources] started pid 4646
Aug 29 16:22:06 Node2 heartbeat[4646]: info: Giving up all HA resources.
Aug 29 16:22:06 Node2 heartbeat: info: Releasing resource group: Node1 IPaddr2::192.168.8.150/24/eth0:fs
Aug 29 16:22:06 Node2 heartbeat: info: Running /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop
Aug 29 16:22:06 Node2 heartbeat: debug: Starting /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop
Aug 29 16:22:06 Node2 heartbeat: info: killed previously running send_arp for 192.168.8.150
Aug 29 16:22:06 Node2 heartbeat: info: /sbin/ip -f inet addr delete 192.168.8.150 dev eth0
Aug 29 16:22:06 Node2 heartbeat: info: /sbin/ip -o -f inet addr show eth0
Aug 29 16:22:06 Node2 heartbeat: info: IP Address 192.168.8.150 released
Aug 29 16:22:06 Node2 heartbeat: debug: /etc/ha.d/resource.d/IPaddr2 192.168.8.150/24/eth0:fs stop done. RC=0
Aug 29 16:22:06 Node2 heartbeat[4646]: info: killing heartbeat resource child process group 4640 with signal 9
Aug 29 16:22:06 Node2 heartbeat[4646]: info: All HA resources relinquished.
Aug 29 16:22:06 Node2 heartbeat[4646]: debug: Sending T_SHUTDONE.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Received T_SHUTDONE from us.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: Calling hb_mcp_final_shutdown in a second.
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: RscMgmtProc 'hb_giveup_resources' exited code 0
Aug 29 16:22:06 Node2 heartbeat[4098]: info: other_holds_resources: 2
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:06 Node2 heartbeat[4098]: info: other_holds_resources: 3
Aug 29 16:22:06 Node2 heartbeat[4098]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 5
Aug 29 16:22:45 Node2 heartbeat[4098]: debug: hb_mcp_final_shutdown() phase 0
Aug 29 16:22:46 Node2 heartbeat[4098]: debug: hb_mcp_final_shutdown() phase 1
Aug 29 16:22:46 Node2 heartbeat[4098]: info: killing HBFIFO process 4174 with signal 15
Aug 29 16:22:46 Node2 heartbeat[4098]: info: killing HBWRITE process 4175 with signal 15
Aug 29 16:22:46 Node2 heartbeat[4098]: info: killing HBREAD process 4176 with signal 15
Aug 29 16:22:46 Node2 heartbeat[4098]: info: killing HBWRITE process 4177 with signal 15
Aug 29 16:22:46 Node2 heartbeat[4098]: info: killing HBREAD process 4178 with signal 15
Aug 29 16:22:46 Node2 heartbeat[4175]: debug: Process 4175 processing SIGTERM
Aug 29 16:22:46 Node2 heartbeat[4174]: debug: Process 4174 processing SIGTERM
Aug 29 16:22:46 Node2 heartbeat[4174]: debug: Exiting from pid 4174 [rc=15]
Aug 29 16:22:46 Node2 heartbeat[4175]: debug: Exiting from pid 4175 [rc=15]
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Core process 4174 exited. 5 remaining
Aug 29 16:22:46 Node2 heartbeat[4176]: debug: Process 4176 processing SIGTERM
Aug 29 16:22:46 Node2 heartbeat[4176]: debug: Exiting from pid 4176 [rc=15]
Aug 29 16:22:46 Node2 heartbeat[4177]: debug: Process 4177 processing SIGTERM
Aug 29 16:22:46 Node2 heartbeat[4177]: debug: Exiting from pid 4177 [rc=15]
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Core process 4175 exited. 4 remaining
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Core process 4176 exited. 3 remaining
Aug 29 16:22:46 Node2 heartbeat[4178]: debug: Process 4178 processing SIGTERM
Aug 29 16:22:46 Node2 heartbeat[4178]: debug: Exiting from pid 4178 [rc=15]
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Core process 4177 exited. 2 remaining
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Core process 4178 exited. 1 remaining
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Heartbeat shutdown complete.
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Heartbeat restart triggered.
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Restarting heartbeat.
Aug 29 16:22:46 Node2 heartbeat[4098]: info: Performing heartbeat restart exec.
Aug 29 16:23:02 Node2 ntpd[3870]: adjusting local clock by 0.416000s
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(keepalive,5)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(warntime,10)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(deadtime,20)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(initdead,40)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(auto_failback,off)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(udpport,694)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(node,Node1)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(node,Node2)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Adding [ug]id hacluster [104] to authorization g_hash_table
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Adding [ug]id haclient [106] to authorization g_hash_table
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Beginning authentication parsing
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: 16 max authentication methods
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Keyfile opened
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Keyfile perms OK
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: 16 max authentication methods
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Found authentication method [md5]
Aug 29 16:23:07 Node2 heartbeat[4098]: info: AUTH: i=1: key = 0x80d8e94, auth=0xb7e2646c, authname=md5
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Outbound signing method is 1
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: Authentication parsing complete [1]
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(hopfudge,1)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(baud,19200)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(hbgenmethod,file)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(realtime,true)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(normalpoll,true)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(msgfmt,classic)
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: add_option(log_badpack,true)
Aug 29 16:23:07 Node2 heartbeat[4098]: info: **************************
Aug 29 16:23:07 Node2 heartbeat[4098]: info: Configuration validated. Starting heartbeat 1.2.4
Aug 29 16:23:07 Node2 heartbeat[4098]: debug: HA configuration OK.  Heartbeat starting.
Aug 29 16:23:07 Node2 heartbeat[4737]: info: heartbeat: version 1.2.4
Aug 29 16:23:07 Node2 heartbeat[4737]: info: Heartbeat generation: 31
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: bound send socket to device: eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: bound receive socket to device: eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: started on port 694 interface eth0 to 192.168.8.151
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: ucast channel eth0 now open...
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: opening ucast eth0 (UDP/IP unicast)
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: write socket priority set to IPTOS_LOWDELAY on eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: bound send socket to device: eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: bound receive socket to device: eth0
Aug 29 16:23:07 Node2 heartbeat[4737]: info: ucast: started on port 694 interface eth0 to 192.168.8.152
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: ucast channel eth0 now open...
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: FIFO process pid: 4743
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: write process pid: 4744
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: read child process pid: 4745
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: write process pid: 4746
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: read child process pid: 4747
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: Limiting CPU: 30 CPU seconds every 60000 milliseconds
Aug 29 16:23:07 Node2 heartbeat[4737]: info: pid 4737 locked in memory.
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: Waiting for child processes to start
Aug 29 16:23:07 Node2 heartbeat[4737]: info: Local status now set to: 'up'
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: All your child process are belong to us
Aug 29 16:23:07 Node2 heartbeat[4737]: debug: Starting local status message @ 5000 ms intervals
Aug 29 16:23:08 Node2 heartbeat[4743]: info: pid 4743 locked in memory.
Aug 29 16:23:08 Node2 heartbeat[4743]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:08 Node2 heartbeat[4744]: info: pid 4744 locked in memory.
Aug 29 16:23:08 Node2 heartbeat[4744]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:23:08 Node2 heartbeat[4745]: info: pid 4745 locked in memory.
Aug 29 16:23:08 Node2 heartbeat[4745]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:08 Node2 heartbeat[4746]: info: pid 4746 locked in memory.
Aug 29 16:23:08 Node2 heartbeat[4747]: info: pid 4747 locked in memory.
Aug 29 16:23:08 Node2 heartbeat[4746]: debug: Limiting CPU: 24 CPU seconds every 60000 milliseconds
Aug 29 16:23:08 Node2 heartbeat[4747]: debug: Limiting CPU: 6 CPU seconds every 60000 milliseconds
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Link Node1:eth0 up.
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: CreateInitialFilter: ip-request-resp
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: CreateInitialFilter: ask_resources
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: CreateInitialFilter: status
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: CreateInitialFilter: hb_takeover
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: CreateInitialFilter: ip-request
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Status update for node Node1: status up
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Status seqno: 1 msgtime: 1188397390
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: notify_world: invoking harc: OLD status: up
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Process [status] started pid 4748
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Starting notify process [status]
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Comm_now_up(): updating status to active
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Local status now set to: 'active'
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Sending local starting msg: resourcestate = 0
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 0
Aug 29 16:23:11 Node2 heartbeat[4748]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:23:11 Node2 heartbeat[4748]: debug: notify_world: Running harc status
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Status update for node Node1: status active
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Status seqno: 3 msgtime: 1188397391
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: StartNextRemoteRscReq(): child count 1
Aug 29 16:23:11 Node2 heartbeat[4737]: info: AnnounceTakeover(local 0, foreign 1, reason 'HB_R_BOTHSTARTING' (0))
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: process_resources: other now unstable
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Sending hold resources msg: none, stable=0 # <none>
Aug 29 16:23:11 Node2 heartbeat[4737]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:23:11 Node2 heartbeat[4737]: info: STATE 1 => 3
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:23:11 Node2 heartbeat[4737]: info: STATE 3 => 2
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 2
Aug 29 16:23:11 Node2 heartbeat[4737]: info: AnnounceTakeover(local 0, foreign 1, reason 'T_RESOURCES' (0))
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: process_resources(2):  other now unstable
Aug 29 16:23:11 Node2 heartbeat[4737]: info: other_holds_resources: 0
Aug 29 16:23:11 Node2 heartbeat[4737]: info: STATE 2 => 3
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 3
Aug 29 16:23:11 Node2 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Exiting status process 4748 returned rc 0.
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: StartNextRemoteRscReq() - calling hook
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: notify_world: invoking harc: OLD status: active
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Process [status] started pid 4752
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: Starting notify process [status]
Aug 29 16:23:11 Node2 heartbeat[4752]: debug: notify_world: setting SIGCHLD Handler to SIG_DFL
Aug 29 16:23:11 Node2 heartbeat[4752]: debug: notify_world: Running harc status
Aug 29 16:23:11 Node2 heartbeat: info: Running /etc/ha.d/rc.d/status status
Aug 29 16:23:11 Node2 heartbeat[4737]: info: Exiting status process 4752 returned rc 0.
Aug 29 16:23:11 Node2 heartbeat[4737]: debug: RscMgmtProc 'status' exited code 0
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: Process [req_our_resources(ask)] started pid 4756
Aug 29 16:23:22 Node2 heartbeat[4737]: info: local resource transition completed.
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: Sending hold resources msg: local, stable=1 # <none>
Aug 29 16:23:22 Node2 heartbeat[4737]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (0))
Aug 29 16:23:22 Node2 heartbeat[4737]: info: Initial resource acquisition complete (T_RESOURCES(us))
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 0, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:22 Node2 heartbeat[4756]: debug: req_our_resources(/usr/lib/heartbeat/ResourceManager listkeys Node2)
Aug 29 16:23:22 Node2 heartbeat[4737]: info: remote resource transition completed.
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: Sending hold resources msg: local, stable=1 # <none>
Aug 29 16:23:22 Node2 heartbeat[4737]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: Calling PerformAutoFailback()
Aug 29 16:23:22 Node2 heartbeat[4737]: info: other_holds_resources: 1
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:22 Node2 heartbeat[4737]: info: other_holds_resources: 1
Aug 29 16:23:22 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node2 heartbeat[4756]: info: No local resources [/usr/lib/heartbeat/ResourceManager listkeys Node2] to acquire.
Aug 29 16:23:23 Node2 heartbeat[4756]: debug: Sending hold resources msg: local, stable=1 # req_our_resources()
Aug 29 16:23:23 Node2 heartbeat[4737]: info: AnnounceTakeover(local 1, foreign 1, reason 'T_RESOURCES(us)' (1))
Aug 29 16:23:23 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 1, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4
Aug 29 16:23:23 Node2 heartbeat[4737]: info: Exiting req_our_resources(ask) process 4756 returned rc 0.
Aug 29 16:23:23 Node2 heartbeat[4737]: debug: RscMgmtProc 'req_our_resources(ask)' exited code 0
Aug 29 16:23:23 Node2 heartbeat[4737]: info: other_holds_resources: 1
Aug 29 16:23:23 Node2 heartbeat[4737]: debug: hb_rsc_isstable: ResourceMgmt_child_count: 0, other_is_stable: 1, takeover_in_progress: 0, going_standby: 0, standby running(ms): 0, resourcestate: 4






haresources:
Node1 IPaddr2::192.168.8.150/24/eth0:fs

ha.cf:
debugfile /var/log/ha-debug
logfile /var/log/ha-log
logfacility daemon
coredumps false
debug 1
keepalive 5
warntime 10
deadtime 20
initdead 40
auto_failback off
ucast eth0 192.168.8.151
ucast eth0 192.168.8.152
udpport 694
node Node1
node Node2


Thank you!

-- 
    <) .--.
    )#=+  '
   /## |     .+.                                   Greetings,
,,/###,|,,,,,,|,,,,                                Michael




More information about the Linux-HA mailing list