[Drbd-dev] DRBD Reconnection Bug

[Lars Ellenberg]

On Tue, Jul 01, 2008 at 11:08:41AM +0200, Lars Ellenberg wrote:
> On Mon, Jun 30, 2008 at 11:29:13PM -0700, John Muth wrote:
> > I've been testing DRBD 8.2.6 on top of Centos 5.1 for use in a lights-out
> > environment.
> > 
> > I think I ran across a bug.Ha sanyone seen anything like this:
> > 
> > Background:
> > 
> > I'm running DRBD on top of LVM. I have a LVM volume named 'sm-vol' on two nodes
> > and I've got /dev/drbd0 mapped to it. I replicate using 'protocol C'. At the
> > beginning of the test node A is the primary and node B is the secondary. My
> > test script does:
> > 
> >   1. Write verifiable data to /dev/drbd0 on node A. Create a LVM snapshot on
> > node B and verify the data.
> >   2. Bring down node B using 'service drbd stop' Write more data frm node A.
> > Bring the node B back up with 'service drbd start'. When re-sync is complete,
> > create a LVM snapshot on the node B and verify that the contents match what was
> > written by the node A.
> >   3. Bring down node A with 'service drbd stop'. Make the node B into the
> > primary (drbdadm primary sm-vol). Write more data to the /dev/drbd0 from node
> > B.. Bring node A back with 'service drbd start'. Wait for resync to complete.
> > Create LVM snapshot on node A and erify data.
> >   4. Run 'drbdadm secondary sm-vol' on node B followed by 'drbdadm primary
> > sm-vol' on node A.
> >   5  Repeat
> > 
> > Once every 100 or so loops, DRBD gets wedged during a reconnection. When the
> > system gets wedged, I do 'cat /etc/drbd' on both nodes and I see the following:
> > 
> > On primary:
> > 
> > [root at vm5 ~]# cat /proc/drbd
> > version: 8.2.6 (api:88/proto:86-88)
> > GIT-hash: 3e69822d3bb4920a8c1bfdf7d647169eba7d2eb4 build by
> > buildsvn at c5-i386-build, 2008-06-26 16:40:17
> >  0: cs:WFBitMapS st:Primary/Secondary ds:UpToDate/Outdated C r---
> >     ns:288064 nr:94516 dw:613836 dr:845384 al:122 bm:31 lo:0 pe:0 ua:0 ap:0
> > oos:95888
> > 
> > On secondary:
> > 
> > [root at vm6 ~]# cat /proc/drbd
> > version: 8.2.6 (api:88/proto:86-88)
> > GIT-hash: 3e69822d3bb4920a8c1bfdf7d647169eba7d2eb4 build by
> > buildsvn at c5-i386-build, 2008-06-26 16:40:17
> >  0: cs:WFBitMapT st:Secondary/Primary ds:Negotiating/UpToDate C r---
> >     ns:0 nr:0 dw:0 dr:0 al:106 bm:93 lo:0 pe:0 ua:0 ap:0 oos:95888
> > 
> > /var/log/messages looks like:
> > 
> > On primary:
> > 
> > Jun 30 13:30:08 vm5 kernel: drbd0: peer( Secondary -> Unknown ) conn( Connected
> > -> TearDown ) pdsk( UpToDate -> DUnknown )
> 
> > On secondary:
> > 
> > Jun 30 13:28:46 vm6 kernel: drbd0: peer( Primary -> Unknown ) conn( Connected
> > -> NetworkFailure ) pdsk( UpToDate -> DUnknown )
> 
> since you can "easily" reproduce this,
> please get the time in sync on those boxes (ntp),
> makes it much easier to read logs.
> 
> then post new logs.

but.

> Jun 30 13:28:46 vm6 kernel: drbd0: receiver (re)started
> Jun 30 13:28:46 vm6 kernel: drbd0: conn( Unconnected -> WFConnection )
> Jun 30 13:28:46 vm6 kernel: drbd0: disk( UpToDate -> Diskless )
> Jun 30 13:28:46 vm6 kernel: drbd0: Handshake successful: Agreed network protocol version 88
> Jun 30 13:28:46 vm6 kernel: drbd0: conn( WFConnection -> WFReportParams )
> Jun 30 13:28:46 vm6 kernel: drbd0: Starting asender thread (from drbd0_receiver [9457])
> Jun 30 13:28:46 vm6 kernel: drbd0: data-integrity-alg: <not-used>
> Jun 30 13:28:46 vm6 kernel: drbd0: peer( Unknown -> Primary ) conn( WFReportParams -> Connected ) pdsk( DUnknown -> UpToDate )

hm. going Connected while still "Diskless"...

> Jun 30 13:28:55 vm6 kernel: drbd0: disk( Diskless -> Attaching )

then attaching the disk,

> Jun 30 13:28:55 vm6 kernel: drbd0: Found 4 transactions (145 active extents) in activity log.
> Jun 30 13:28:55 vm6 kernel: drbd0: max_segment_size ( = BIO size ) = 32768
> Jun 30 13:28:55 vm6 kernel: drbd0: reading of bitmap took 1 jiffies
> Jun 30 13:28:55 vm6 kernel: drbd0: recounting of set bits took additional 0 jiffies
> Jun 30 13:28:55 vm6 kernel: drbd0: 0 KB (0 bits) marked out-of-sync by on disk bit-map.
> Jun 30 13:28:55 vm6 kernel: drbd0: disk( Attaching -> Negotiating )

going "Negotiating"

> Jun 30 13:28:55 vm6 kernel: drbd0: Writing meta data super block now.


> Jun 30 13:28:55 vm6 kernel: drbd0: unexpected cstate (Connected) in receive_bitmap

right there.

> Jun 30 13:28:55 vm6 kernel: drbd0: conn( Connected -> WFBitMapT )

according to this, it likely is a race between attaching the disk and
establishing the connection.  we had similar races before, the were
believed to be fixed :(

do you mind retrying with the latest git checkout?

can you please post your excerciser script?
which drbdadm / drbdsetup commands get executed in which order?


-- 
: Lars Ellenberg                            Tel +43-1-8178292-55 :
: LINBIT Information Technologies GmbH      Fax +43-1-8178292-82 :
: Vivenotgasse 48, A-1120 Vienna/Europe    http://www.linbit.com :