[Drbd-dev] DRBD8: incorrect state transition Connected ->WFBitMapS and UpToDate->Inconsistent

Montrose, Ernest Ernest.Montrose at stratus.com
Mon Nov 12 14:41:10 CET 2007


Hi,
We have been struggling with a problem where one side gets stuck in
WFBitMapS and Inconsistent State. Consider two nodes (Node0 and node1).


* Device r5 on node0 starts syncing as the synctarget.
* Device r5 is done syncing and on node0 we call drbd_resync_finished()
this gets delayed for a bit in drbd_rs_del_all()
* During this delay, device R0   wants to resync.  So the lower priority
devices like R5 gets paused.  This is were the trouble starts.
* drbd_resync_finished() is not done on node0.
* node0 goes "Connected" and sends its states to node1 and that triggers
a sync_handshake() which results in Connected ->WFBitMapS and
UpToDate->Inconsistent. We are stuck there.

So the problem, I think, is that while the synctarget is in
drbd_resync_finished() for a bit, a state change can occur causing the
peer that already finished to go into WFBitMapS and beyond.

We had a couple of ideas on how this may be fixed:
1) 
We could find a way to NOT actually pause the sync _if_ the sync is in
fact already completed -- Perhaps modifying the pause-resync stuff so it
doesn't do it if there's nothing left to be resunk? (or if we're already
in the drbd_resync_finished processing - I dont know that there's a way
to tell this though).
I attempted to implement this a couple of ways but failed.

2) 
* Don't call drbd_sync_handshake() if the peer state is > Connected.
AND...
* Send the synctarget states to the peer when the stalled sync is done.
This is suspiciously problematic but seems to actually close the racy
window.  I include the implementation as a patch here.

ANY other Ideas please??

Below is a set of logs when the problem occurs:

On node0:
Oct  4 14:55:58 node0 kernel: drbd60: Began resync as PausedSyncT (will
sync 768 KB [192 bits set]).
Oct  4 14:55:58 node0 kernel: drbd60: Writing meta data super block now.
Oct  4 14:55:59 node0 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:56:00 node0 kernel: drbd60: conn( PausedSyncT -> SyncTarget )
peer_isp( 1 -> 0 )
Oct  4 14:56:00 node0 kernel: drbd60: Syncer continues.
Oct  4 14:56:00 node0 kernel: drbd60: conn( SyncTarget -> PausedSyncT )
aftr_isp( 0 -> 1 )
Oct  4 14:56:00 node0 kernel: drbd60: Resync suspended
Oct  4 14:56:01 node0 kernel: drbd60: conn( PausedSyncT -> SyncTarget )
aftr_isp( 1 -> 0 )
Oct  4 14:56:01 node0 kernel: drbd60: Syncer continues.
Oct  4 14:56:01 node0 kernel: drbd60: ASSERT(
!test_bit(STOP_SYNC_TIMER,&mdev->flags) ) in
/sandbox/sgraham/sn/trunk/platform/drbd/src/drbd/drbd_main.c:786
Oct  4 14:56:01 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:01 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:01 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:03 node0 kernel: drbd60: conn( SyncTarget -> PausedSyncT )
aftr_isp( 0 -> 1 )
Oct  4 14:56:03 node0 kernel: drbd60: Resync suspended
Oct  4 14:56:03 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:05 node0 kernel: drbd60: conn( PausedSyncT -> SyncTarget )
aftr_isp( 1 -> 0 )
Oct  4 14:56:05 node0 kernel: drbd60: Syncer continues.
Oct  4 14:56:05 node0 kernel: drbd60: ASSERT(
!test_bit(STOP_SYNC_TIMER,&mdev->flags) ) in
/sandbox/sgraham/sn/trunk/platform/drbd/src/drbd/drbd_main.c:786
Oct  4 14:56:05 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:06 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:07 node0 kernel: drbd60: conn( SyncTarget -> PausedSyncT )
aftr_isp( 0 -> 1 )
Oct  4 14:56:07 node0 kernel: drbd60: Resync suspended
Oct  4 14:56:07 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:07 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node0 kernel: drbd60: conn( PausedSyncT -> SyncTarget )
aftr_isp( 1 -> 0 )
Oct  4 14:56:09 node0 kernel: drbd60: Syncer continues.
Oct  4 14:56:09 node0 kernel: drbd60: ASSERT(
!test_bit(STOP_SYNC_TIMER,&mdev->flags) ) in
/sandbox/sgraham/sn/trunk/platform/drbd/src/drbd/drbd_main.c:786
Oct  4 14:56:09 node0 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node0 kernel: drbd60: Resync done (total 2 sec; paused 0
sec; 384 K/sec)
Oct  4 14:56:09 node0 kernel: drbd60: conn( SyncTarget -> Connected )
disk( Inconsistent -> UpToDate )
Oct  4 14:56:09 node0 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:09 node0 kernel: drbd60: Resync done (total 2 sec; paused 0
sec; 0 K/sec)
Oct  4 14:56:09 node0 kernel: drbd60: Resync done (total 2 sec; paused 0
sec; 0 K/sec)
Oct  4 14:56:09 node0 kernel: drbd60: Connected in w_make_resync_request
Oct  4 14:56:09 node0 kernel: drbd60: Resync done (total 2 sec; paused 0
sec; 0 K/sec)
Oct  4 14:56:10 node0 kernel: drbd60: unexpected cstate (Connected) in
receive_bitmap
Oct  4 14:56:10 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:56:10 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:32 node0 kernel: drbd60: aftr_isp( 0 -> 1 )
Oct  4 14:57:33 node0 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:57:35 node0 kernel: drbd60: aftr_isp( 0 -> 1 )
Oct  4 14:57:36 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:36 node0 kernel: drbd60: peer_isp( 0 -> 1 )
Oct  4 14:57:36 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:36 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:36 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:37 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:37 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:39 node0 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:57:39 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!
Oct  4 14:57:39 node0 kernel: drbd60: peer_isp( 1 -> 0 )
Oct  4 14:57:39 node0 kernel: drbd60: No resync, but 1048535 bits in
bitmap!

#################On node1###################
Oct  4 14:55:58 node1 kernel: drbd60: Began resync as PausedSyncS (will
sync 768 KB [192 bits set]).
Oct  4 14:55:58 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:00 node1 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:56:00 node1 kernel: drbd60: conn( PausedSyncS -> SyncSource )
peer_isp( 1 -> 0 )
Oct  4 14:56:00 node1 kernel: drbd60: Syncer continues.
Oct  4 14:56:01 node1 kernel: drbd60: conn( SyncSource -> PausedSyncS )
aftr_isp( 0 -> 1 )
Oct  4 14:56:01 node1 kernel: drbd60: Resync suspended
Oct  4 14:56:01 node1 kernel: drbd60: conn( PausedSyncS -> SyncSource )
aftr_isp( 1 -> 0 )
Oct  4 14:56:01 node1 kernel: drbd60: Syncer continues.
Oct  4 14:56:01 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:04 node1 kernel: drbd60: conn( SyncSource -> PausedSyncS )
aftr_isp( 0 -> 1 )
Oct  4 14:56:04 node1 kernel: drbd60: Resync suspended
Oct  4 14:56:04 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:05 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:06 node1 kernel: drbd60: conn( PausedSyncS -> SyncSource )
aftr_isp( 1 -> 0 )
Oct  4 14:56:06 node1 kernel: drbd60: Syncer continues.
Oct  4 14:56:06 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:08 node1 kernel: drbd60: conn( SyncSource -> PausedSyncS )
aftr_isp( 0 -> 1 )
Oct  4 14:56:08 node1 kernel: drbd60: Resync suspended
Oct  4 14:56:08 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:08 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node1 kernel: drbd60: conn( PausedSyncS -> SyncSource )
aftr_isp( 1 -> 0 )
Oct  4 14:56:09 node1 kernel: drbd60: Syncer continues.
Oct  4 14:56:09 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node1 kernel: drbd60: Retrying drbd_rs_del_all() later.
refcnt=1
Oct  4 14:56:09 node1 kernel: drbd60: Resync done (total 1 sec; paused 0
sec; 768 K/sec)
Oct  4 14:56:09 node1 kernel: drbd60: conn( SyncSource -> Connected )
pdsk( Inconsistent -> UpToDate )
Oct  4 14:56:09 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:09 node1 kernel: drbd60: Resync done (total 2 sec; paused 0
sec; 0 K/sec)
Oct  4 14:56:10 node1 kernel: drbd60: Becoming sync source due to disk
states.
Oct  4 14:56:10 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:10 node1 kernel: drbd60: writing of bitmap took 2 jiffies
Oct  4 14:56:10 node1 kernel: drbd60: 4095 MB marked out-of-sync by on
disk bit-map.
Oct  4 14:56:10 node1 kernel: drbd60: 4194140 KB now marked out-of-sync
by on disk bit-map.
Oct  4 14:56:10 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:10 node1 kernel: drbd60: conn( Connected -> WFBitMapS )
pdsk( UpToDate -> Inconsistent )
Oct  4 14:56:10 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:56:10 node1 kernel: drbd60: pdsk( Inconsistent -> UpToDate )
Oct  4 14:56:10 node1 kernel: drbd60: Writing meta data super block now.
Oct  4 14:57:34 node1 kernel: drbd60: aftr_isp( 0 -> 1 )
Oct  4 14:57:35 node1 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:57:35 node1 kernel: drbd60: aftr_isp( 0 -> 1 )
Oct  4 14:57:35 node1 kernel: drbd60: peer_isp( 0 -> 1 )
Oct  4 14:57:35 node1 kernel: drbd60: peer_isp( 1 -> 0 )
Oct  4 14:57:35 node1 kernel: drbd60: peer_isp( 0 -> 1 )
Oct  4 14:57:40 node1 kernel: drbd60: aftr_isp( 1 -> 0 )
Oct  4 14:57:40 node1 kernel: drbd60: peer_isp( 1 -> 0 )
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Wbimaps_stuck.patch
Type: application/octet-stream
Size: 1105 bytes
Desc: Wbimaps_stuck.patch
Url : http://lists.linbit.com/pipermail/drbd-dev/attachments/20071112/9a1721e6/Wbimaps_stuck.obj


More information about the drbd-dev mailing list