Note: "permalinks" may not be as permanent as we would like,
direct links of old sources may well be a few messages off.
I've seen similar problems described in the list a
couple times before, but none of the proposed fixes
worked. Please help. Many thanks in advance!
Setup:
2 identical servers with Fedora Core 3,
2.6.10-1.770smp, drbd-0.7.10, heartbeat-1.2.3
Problem:
Everything seems to work perfectly when primary
(cluster1) fails after "hb_standby" command or by
hitting the reset button. Secondary (cluster2) takes
over the drbd just fine.
If the primary (cluster1) is nicely rebooted with
"shutdown -r" command, secondary (cluster2) takes over
the drbd without any issues, but when the (cluster1)
comes back up, the drbd would not reconnect, because
drbd tries to make the primary server the target.
***
version: 0.7.10 (api:77/proto:74)
SVN Revision: 1743 build by @cluster1, 2005-03-11
14:14:04
0: cs:WFConnection st:Secondary/Unknown ld:Consistent
ns:0 nr:0 dw:0 dr:0 al:0 bm:12 lo:0 pe:0 ua:0 ap:0
***
version: 0.7.10 (api:77/proto:74)
SVN Revision: 1743 build by @cluster2, 2005-03-11
14:14:24
0: cs:StandAlone st:Primary/Unknown ld:Consistent
ns:0 nr:46592 dw:55492 dr:9136 al:0 bm:4 lo:0 pe:0
ua:0 ap:0
*** cluster1 /var/log/messages ***
Mar 11 16:17:52 cluster1 init: Switching to runlevel:
6
Mar 11 16:17:53 cluster1 cups-config-daemon:
cups-config-daemon -TERM succeeded
Mar 11 16:17:53 cluster1 haldaemon: haldaemon -TERM
succeeded
Mar 11 16:17:53 cluster1 messagebus: messagebus -TERM
succeeded
Mar 11 16:17:53 cluster1 atd: atd shutdown succeeded
Mar 11 16:17:53 cluster1 drbd: Stopping all DRBD
resources
Mar 11 16:17:53 cluster1 drbd: ioctl(,SET_STATE,)
failed:
Mar 11 16:17:53 cluster1 drbd: Device or resource busy
Mar 11 16:17:53 cluster1 drbd: Someone has opened the
device for RW access!
Mar 11 16:17:53 cluster1 drbd: Command
'/sbin/drbdsetup /dev/drbd0 down' terminated with exit
code 20
Mar 11 16:17:53 cluster1 drbd: drbdsetup exited with
code 20
Mar 11 16:17:53 cluster1 drbd: ERROR: Module drbd is
in use
Mar 11 16:17:53 cluster1 drbd: .
Mar 11 16:17:53 cluster1 rc: Stopping drbd: succeeded
Mar 11 16:17:53 cluster1 cups: cupsd shutdown
succeeded
Mar 11 16:17:53 cluster1 xfs[3950]: terminating
Mar 11 16:17:54 cluster1 xfs: xfs shutdown succeeded
Mar 11 16:17:54 cluster1 gpm: gpm shutdown succeeded
Mar 11 16:17:54 cluster1 sshd: sshd -TERM succeeded
Mar 11 16:17:54 cluster1 smartd[3731]: smartd received
signal 15: Terminated
Mar 11 16:17:54 cluster1 smartd[3731]: smartd is
exiting (exit status 0)
Mar 11 16:17:54 cluster1 smartd: smartd shutdown
succeeded
Mar 11 16:17:54 cluster1 xinetd[3863]: Exiting...
Mar 11 16:17:54 cluster1 xinetd: xinetd shutdown
succeeded
Mar 11 16:17:54 cluster1 acpid: acpid shutdown
succeeded
Mar 11 16:17:54 cluster1 crond: crond shutdown
succeeded
Mar 11 16:17:54 cluster1 mDNSResponder: mDNSResponder
shutdown succeeded
Mar 11 16:17:54 cluster1 nifd: nifd shutdown succeeded
Mar 11 16:17:55 cluster1 ntpd[3904]: ntpd exiting on
signal 15
Mar 11 16:17:55 cluster1 ntpd: ntpd shutdown succeeded
Mar 11 16:17:55 cluster1 mdmonitor: mdadm shutdown
succeeded
Mar 11 16:17:55 cluster1 nfslock: lockd shutdown
failed
Mar 11 16:17:55 cluster1 rpc.statd[3544]: Caught
signal 15, un-registering and exiting.
Mar 11 16:17:55 cluster1 nfslock: rpc.statd shutdown
succeeded
Mar 11 16:17:55 cluster1 portmap: portmap shutdown
succeeded
Mar 11 16:17:55 cluster1 kernel: Kernel logging (proc)
stopped.
Mar 11 16:17:55 cluster1 kernel: Kernel log daemon
terminating.
Mar 11 16:17:56 cluster1 syslog: klogd shutdown
succeeded
Mar 11 16:17:56 cluster1 exiting on signal 15
[…]
Mar 11 16:20:27 cluster1 drbd: Starting DRBD
resources:
Mar 11 16:20:27 cluster1 kernel: drbd: initialised.
Version: 0.7.10 (api:77/proto:74)
Mar 11 16:20:27 cluster1 kernel: drbd: SVN Revision:
1743 build by @cluster1, 2005-03-11 14:14:04
Mar 11 16:20:27 cluster1 kernel: drbd: registered as
block device major 147
Mar 11 16:20:33 cluster1 drbd: [
Mar 11 16:20:33 cluster1 drbd: d0
Mar 11 16:20:33 cluster1 kernel: drbd0: resync bitmap:
bits=17887616 words=558988
Mar 11 16:20:33 cluster1 kernel: drbd0: size = 68 GB
(71550464 KB)
Mar 11 16:20:33 cluster1 kernel: klogd 1.4.1,
---------- state change ----------
Mar 11 16:20:34 cluster1 kernel: drbd0: 0 KB marked
out-of-sync by on disk bit-map.
Mar 11 16:20:34 cluster1 kernel: drbd0: Found 6
transactions (15 active extents) in activity log.
Mar 11 16:20:34 cluster1 kernel: drbd0: Marked
additional 5824 KB as out-of-sync based on AL.
Mar 11 16:20:34 cluster1 kernel: drbd0: drbdsetup
[3970]: cstate Unconfigured --> StandAlone
Mar 11 16:20:34 cluster1 drbd: s0
Mar 11 16:20:34 cluster1 drbd: n0
Mar 11 16:20:34 cluster1 kernel: drbd0: drbdsetup
[3983]: cstate StandAlone --> Unconnected
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate Unconnected --> WFConnection
Mar 11 16:20:34 cluster1 drbd: ]
Mar 11 16:20:34 cluster1 drbd: .
Mar 11 16:20:34 cluster1 drbd: WARN: stdin/stdout is
not a TTY; using /dev/console
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate WFConnection --> WFReportParams
Mar 11 16:20:34 cluster1 kernel: drbd0: Handshake
successful: DRBD Network Protocol version 74
Mar 11 16:20:34 cluster1 kernel: drbd0: Connection
established.
Mar 11 16:20:34 cluster1 kernel: drbd0: I am(S):
1:0000000a:00000005:0000008d:00000015:10
Mar 11 16:20:34 cluster1 kernel: drbd0: Peer(P):
1:0000000a:00000005:0000008b:00000016:10
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate WFReportParams --> WFBitMapS
Mar 11 16:20:34 cluster1 kernel: drbd0: sock_sendmsg
returned -32
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate WFBitMapS --> BrokenPipe
Mar 11 16:20:34 cluster1 kernel: drbd0: short sent
ReportBitMap size=4096 sent=0
Mar 11 16:20:34 cluster1 kernel: drbd0:
Secondary/Unknown --> Secondary/Primary
Mar 11 16:20:34 cluster1 kernel: drbd0: meta
connection shut down by peer.
Mar 11 16:20:34 cluster1 kernel: drbd0: asender
terminated
Mar 11 16:20:34 cluster1 kernel: drbd0: sock was shut
down by peer
Mar 11 16:20:34 cluster1 drbd: WARN: stdin/stdout is
not a TTY; using /dev/console
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate BrokenPipe --> BrokenPipe
Mar 11 16:20:34 cluster1 rc: Starting drbd: succeeded
Mar 11 16:20:34 cluster1 kernel: drbd0: short read
expecting header on sock: r=0
Mar 11 16:20:34 cluster1 kernel: drbd0: worker
terminated
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate BrokenPipe --> Unconnected
Mar 11 16:20:34 cluster1 kernel: drbd0: Connection
lost.
Mar 11 16:20:34 cluster1 kernel: drbd0: drbd0_receiver
[3984]: cstate Unconnected --> WFConnection
Mar 11 16:20:34 cluster1 kernel: Software Watchdog
Timer: 0.07 initialized. soft_noboot=0 soft_margin=60
sec (nowayout= 0)
Mar 11 16:20:34 cluster1 heartbeat[4080]: info:
**************************
Mar 11 16:20:34 cluster1 heartbeat[4080]: info:
Configuration validated. Starting heartbeat 1.2.3
Mar 11 16:20:34 cluster1 heartbeat[4081]: info:
heartbeat: version 1.2.3
Mar 11 16:20:34 cluster1 gpm[4090]: *** info
[startup.c(95)]:
Mar 11 16:20:34 cluster1 gpm[4090]: Started gpm
successfully. Entered daemon mode.
Mar 11 16:20:34 cluster1 heartbeat[4081]: info:
Heartbeat generation: 36
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: ucast:
write socket priority set to IPTOS_LOWDELAY on eth1
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: ucast:
bound send socket to device: eth1
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: ucast:
bound receive socket to device: eth1
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: ucast:
started on port 694 interface eth1 to 192.168.0.2
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: ping
heartbeat started.
Mar 11 16:20:34 cluster1 heartbeat[4081]: notice:
Using watchdog device: /dev/watchdog
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: pid
4081 locked in memory.
Mar 11 16:20:34 cluster1 heartbeat[4081]: info: Local
status now set to: 'up'
[…]
Mar 11 16:20:35 cluster1 heartbeat[4092]: info: pid
4092 locked in memory.
Mar 11 16:20:35 cluster1 heartbeat[4093]: info: pid
4093 locked in memory.
Mar 11 16:20:35 cluster1 heartbeat[4094]: info: pid
4094 locked in memory.
Mar 11 16:20:35 cluster1 heartbeat[4096]: info: pid
4096 locked in memory.
Mar 11 16:20:35 cluster1 heartbeat[4095]: info: pid
4095 locked in memory.
Mar 11 16:20:35 cluster1 heartbeat[4081]: info: Link
192.168.242.254:192.168.242.254 up.
Mar 11 16:20:35 cluster1 heartbeat[4081]: info: Status
update for node 192.168.242.254: status ping
Mar 11 16:20:36 cluster1 rc: Starting readahead:
succeeded
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: Link
cluster2:eth1 up.
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: Status
update for node cluster2: status active
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: Local
status now set to: 'active'
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: remote
resource transition completed.
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: remote
resource transition completed.
Mar 11 16:20:36 cluster1 heartbeat[4081]: info: Local
Resource acquisition completed. (none)
Mar 11 16:20:36 cluster1 heartbeat[4081]: info:
Initial resource acquisition complete
(T_RESOURCES(them))
Mar 11 16:20:36 cluster1 heartbeat: info: Running
/usr/local/etc/ha.d/rc.d/status status
***
*** cluster2 /var/log/messages ***
Mar 11 16:17:56 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Down
Mar 11 16:17:58 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
Mar 11 16:18:06 cluster2 kernel: drbd0: PingAck did
not arrive in time.
Mar 11 16:18:06 cluster2 kernel: drbd0: drbd0_asender
[7614]: cstate Connected --> NetworkFailure
Mar 11 16:18:06 cluster2 kernel: drbd0: asender
terminated
Mar 11 16:18:06 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate NetworkFailure --> BrokenPipe
Mar 11 16:18:06 cluster2 kernel: drbd0: short read
expecting header on sock: r=-512
Mar 11 16:18:06 cluster2 kernel: drbd0: worker
terminated
Mar 11 16:18:06 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate BrokenPipe --> Unconnected
Mar 11 16:18:06 cluster2 kernel: drbd0: Connection
lost.
Mar 11 16:18:06 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate Unconnected --> WFConnection
Mar 11 16:18:13 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Down
Mar 11 16:18:16 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
Mar 11 16:18:21 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Down
Mar 11 16:18:23 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
Mar 11 16:18:54 cluster2 heartbeat[7619]: WARN: node
cluster1: is dead
Mar 11 16:18:54 cluster2 heartbeat[7619]: WARN: No
STONITH device configured.
Mar 11 16:18:54 cluster2 heartbeat[7619]: WARN: Shared
disks are not protected.
Mar 11 16:18:54 cluster2 heartbeat[7619]: info:
Resources being acquired from cluster1.
Mar 11 16:18:54 cluster2 heartbeat[7619]: info: Link
cluster1:eth1 dead.
Mar 11 16:18:54 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/rc.d/status status
Mar 11 16:18:54 cluster2 heartbeat: ERROR: Cannot
locate resource script
Mar 11 16:18:54 cluster2 heartbeat: info: Taking over
resource group drbddisk::r0
Mar 11 16:18:54 cluster2 heartbeat[7665]: info: Local
Resource acquisition completed.
Mar 11 16:18:54 cluster2 heartbeat: info: Acquiring
resource group: cluster1 drbddisk::r0
Filesystem::/dev/drbd0::/data::jfs
Mar 11 16:18:54 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/resource.d/drbddisk r0 start
Mar 11 16:18:54 cluster2 kernel: drbd0:
Secondary/Unknown --> Primary/Unknown
Mar 11 16:18:55 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/resource.d/Filesystem /dev/drbd0
/data jfs start
Mar 11 16:18:55 cluster2 heartbeat: info: Starting
filesystem check on /dev/drbd0
Mar 11 16:18:55 cluster2 heartbeat: info:
/usr/local/lib/heartbeat/mach_down: nice_failback:
foreign resources acquired
Mar 11 16:18:55 cluster2 heartbeat[7619]: info:
mach_down takeover complete.
Mar 11 16:18:55 cluster2 heartbeat: info: mach_down
takeover complete for node cluster1.
Mar 11 16:18:55 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/rc.d/ip-request-resp
ip-request-resp
Mar 11 16:19:49 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Down
Mar 11 16:19:51 cluster2 kernel: e1000: eth1:
e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
Mar 11 16:20:32 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate WFConnection --> WFReportParams
Mar 11 16:20:32 cluster2 kernel: drbd0: Handshake
successful: DRBD Network Protocol version 74
Mar 11 16:20:32 cluster2 kernel: drbd0: Connection
established.
Mar 11 16:20:32 cluster2 kernel: drbd0: I am(P):
1:0000000a:00000005:0000008b:00000016:10
Mar 11 16:20:32 cluster2 kernel: drbd0: Peer(S):
1:0000000a:00000005:0000008d:00000015:10
Mar 11 16:20:32 cluster2 kernel: drbd0: Current
Primary shall become sync TARGET! Aborting to prevent
data corruption.
Mar 11 16:20:32 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate WFReportParams --> StandAlone
Mar 11 16:20:32 cluster2 kernel: drbd0: error
receiving ReportParams, l: 72!
Mar 11 16:20:32 cluster2 kernel: drbd0: worker
terminated
Mar 11 16:20:32 cluster2 kernel: drbd0: asender
terminated
Mar 11 16:20:32 cluster2 kernel: drbd0: drbd0_receiver
[7565]: cstate StandAlone --> StandAlone
Mar 11 16:20:32 cluster2 kernel: drbd0: Connection
lost.
Mar 11 16:20:32 cluster2 kernel: drbd0: receiver
terminated
Mar 11 16:20:34 cluster2 heartbeat[7619]: info:
Heartbeat restart on node cluster1
Mar 11 16:20:34 cluster2 heartbeat[7619]: info: Link
cluster1:eth1 up.
Mar 11 16:20:34 cluster2 heartbeat[7619]: info: Status
update for node cluster1: status up
Mar 11 16:20:34 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/rc.d/status status
Mar 11 16:20:34 cluster2 heartbeat[7619]: info: Status
update for node cluster1: status active
Mar 11 16:20:34 cluster2 heartbeat[7619]: info: remote
resource transition completed.
Mar 11 16:20:34 cluster2 heartbeat: info: Running
/usr/local/etc/ha.d/rc.d/status status
***
*** cluster1,2 drbd.conf ***
resource r0 {
protocol C;
startup {
degr-wfc-timeout 25;
}
disk {
on-io-error detach;
}
net {
timeout 60; # 6 seconds (unit = 0.1
seconds)
connect-int 10; # 10 seconds (unit = 1
second)
ping-int 10; # 10 seconds (unit = 1
second)
}
syncer {
rate 100M;
group 1;
}
on cluster1 {
device /dev/drbd0;
disk /dev/md0;
address 192.168.0.1:7788;
meta-disk internal;
}
on cluster2 {
device /dev/drbd0;
disk /dev/md0;
address 192.168.0.2:7788;
meta-disk internal;
}
}
***
*** cluster1,2 ha.cf ***
debugfile /var/log/ha-debug
logfile /var/log/ha-log
logfacility local0
keepalive 2
deadtime 60
warntime 30
initdead 75
udpport 694
ucast eth1 192.168.0.1
auto_failback off
watchdog /dev/watchdog
node cluster1
node cluster2
ping 192.168.242.254
***
*** cluster1 haresources ***
cluster1 drbddisk::r0
Filesystem::/dev/drbd0::/data::jfs
cluster2
***
__________________________________________________
Do You Yahoo!?
Tired of spam? Yahoo! Mail has the best spam protection around
http://mail.yahoo.com