[Drbd-dev] [PATCH] DRBD 8.0; Make sure barrier is sent after last data block in epoch

[Drbd-dev] [PATCH] DRBD 8.0; Make sure barrier is sent after last data block in epoch

[Graham, Simon]

[-- Attachment #1.1: Type: text/plain, Size: 346 bytes --]

With the new barrier implementation, the code that checks if the size of
the current epoch has hit it's max will queue the work item to send the
barrier BEFORE queuing the workitem to send the last data block in the
epoch which is a problem!

 

Attached patch fixes this by queuing the barrier work item after the
data.

 

Simon


[-- Attachment #1.2: Type: text/html, Size: 3696 bytes --]

[-- Attachment #2: 0001-Make-sure-barrier-is-sent-AFTER-last-data-block-in-e.patch --]
[-- Type: application/octet-stream, Size: 1279 bytes --]

From a474ee80088835f6504a401841fc7eb9e9ed0d9e Mon Sep 17 00:00:00 2001
From: Simon P. Graham <Simon.Graham@stratus.com>
Date: Sun, 27 Jan 2008 10:31:34 -0500
Subject: [PATCH] Make sure barrier is sent AFTER last data block in epoch

---
 drbd/drbd_req.c |   11 ++++++++---
 1 files changed, 8 insertions(+), 3 deletions(-)

diff --git a/drbd/drbd_req.c b/drbd/drbd_req.c
index 8a6f7af..ef39455 100644
--- a/drbd/drbd_req.c
+++ b/drbd/drbd_req.c
@@ -612,14 +612,19 @@ void _req_mod(drbd_request_t *req, drbd_req_event_t what, int error)
 		req->epoch = mdev->newest_barrier->br_number;
 		list_add_tail(&req->tl_requests,&mdev->newest_barrier->requests);
 
-		/* close the epoch, in case it outgrew the limit */
-		if( ++mdev->newest_barrier->n_req >= mdev->net_conf->max_epoch_size )
-			queue_barrier(mdev);
+		/* increment size of current epoch */
+		mdev->newest_barrier->n_req++;
 
+		/* queue work item to send data */
 		D_ASSERT(req->rq_state & RQ_NET_PENDING);
 		req->rq_state |= RQ_NET_QUEUED;
 		req->w.cb =  w_send_dblock;
 		drbd_queue_work(&mdev->data.work, &req->w);
+
+		/* close the epoch, in case it outgrew the limit */
+		if( mdev->newest_barrier->n_req >= mdev->net_conf->max_epoch_size )
+			queue_barrier(mdev);
+
 		break;
 
 	/* FIXME
-- 
1.5.4-rc2.GIT

Re: [Drbd-dev] [PATCH] DRBD 8.0; Make sure barrier is sent after last data block in epoch

[Philipp Reisner]

Hi Simon,

Back from travelling... 

I have applied the two patches you sent Yesterday.
0001-Make-sure-barrier-is-sent-AFTER-last-data-block-in-e.patch
0002-Make-sure-we-dont-set-CREATE_BARRIER-flag-when-conne.patch

BTW, I did white space changes to them. 
  Since we propagate changes from 8.0 to 8.2, and in 8.2 we try
  follow the Linux coding style hard, it makes things easier
  for us when the patches follow the Linux coding style in the
  first place.

From the other patch bomb I still intend to merge 
0010-Ensure-that-state-updates-cannot-be-done-out-of-orde.patch

Regarding the other patches from patch bomb #1, I wanted to
write an summay, which patches where accepted, which are not
yet applied for what reasons. ... But then I went to the
"Open Source Meets Business" Conference and now I can not 
remember... 

Simon, from your point of view, what patches to we missed from
patch bomb #1 ?

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :

RE: [Drbd-dev] [PATCH] DRBD 8.0; Make sure barrier is sent after last data block in epoch

[Graham, Simon]

> BTW, I did white space changes to them.

Sorry - I do try to remember to use the right conventions when editing
these files, but it's different from our internal standard and I
sometimes forget!

> From the other patch bomb I still intend to merge
> 0010-Ensure-that-state-updates-cannot-be-done-out-of-orde.patch
> 
> Regarding the other patches from patch bomb #1, I wanted to
> write an summay, which patches where accepted, which are not
> yet applied for what reasons. ... But then I went to the
> "Open Source Meets Business" Conference and now I can not
> remember...
> 
> Simon, from your point of view, what patches to we missed from
> patch bomb #1 ?

"Patch bomb #1" -- I like it! Here's the set that I think have not been
applied yet (with the git SHA1 ids of the commits in my git repo - I
think these come in the .patch files, right?), including the one you
mentioned above:

. One more place where stop-sync flag is not explicitely cleared when
starting resync (16896a5)
. Ensure that state updated cannot be done out of order whilst running
receive_state (914435c)
. Revert "Fixing "drbdadm pause-sync r0; drbdadm resume-sync r0""
(93144f7)
. Revert "make resync more robust, don't reset find bit offset too
early." (cab2179)

(note on these last two -- the changes you committed actually cause the
sync to stall if paused and resumed quickly. I suspect that some part of
these is probably desired, but you mixed in the changes to the way
resync is restarted which cause the stall so I just backed them out in
toto).

Simon

[Drbd-dev] Stuck in WFBitMapS again

[Montrose, Ernest]

[-- Attachment #1: Type: text/plain, Size: 896 bytes --]


It looks like we still have a race condition while finishing syncing and
pausing/resuming syncing at the same time. 

What's happening is that we finish syncing.
The secondary side goes to Connected at the end of
drbd_resync_finished()

The Primary side is still in drbd_resync_finished().  While still there,

the syncer isp flag gets set and unset due to a higher priority device
syncer getting paused/resumed.

Now the Primary side sends "Inconsistent" state to the Secondary since
we are still in drbd_resync_finished()
and have not gone Connected and UptoDate yet. But the other side is
connected and UpToDate though.

The secondary goes WFBitMapS via drbd_sync_handshake()

In the mean time the Primary finally goes Connected and UptoDate.

The Secondary is stuck in WFBitMapS.

I include a patch that may be the fix for this.  Any other ideas?

Thanks.
EM--


[-- Attachment #2: 4595.patch --]
[-- Type: application/octet-stream, Size: 625 bytes --]

diff --git a/drbd/drbd_receiver.c b/drbd/drbd_receiver.c
index 048a759..184f6df 100644
--- a/drbd/drbd_receiver.c
+++ b/drbd/drbd_receiver.c
@@ -2467,6 +2467,8 @@ STATIC int receive_state(drbd_dev *mdev, Drbd_Header *h)
 			mdev->state.disk == Negotiating));
 		cr |= test_bit(CONSIDER_RESYNC,&mdev->flags); /* peer forced */
 		cr |= (oconn == Connected && peer_state.conn > Connected);
+               cr |= ((oconn == WFBitMapS || oconn == WFBitMapT) && 
+                     peer_state.disk == UpToDate &&  mdev->state.disk == UpToDate);
 
 		if (cr) nconn=drbd_sync_handshake(mdev, peer_state.role, peer_state.disk);
 

Re: [Drbd-dev] Stuck in WFBitMapS again

[Philipp Reisner]

Am Mittwoch, 13. Februar 2008 00:55:51 schrieb Montrose, Ernest:
> It looks like we still have a race condition while finishing syncing and
> pausing/resuming syncing at the same time.
>
> What's happening is that we finish syncing.
> The secondary side goes to Connected at the end of
> drbd_resync_finished()
>
> The Primary side is still in drbd_resync_finished().  While still there,
>
> the syncer isp flag gets set and unset due to a higher priority device
> syncer getting paused/resumed.
>
> Now the Primary side sends "Inconsistent" state to the Secondary since
> we are still in drbd_resync_finished()
> and have not gone Connected and UptoDate yet. But the other side is
> connected and UpToDate though.
>
> The secondary goes WFBitMapS via drbd_sync_handshake()
>
> In the mean time the Primary finally goes Connected and UptoDate.
>
> The Secondary is stuck in WFBitMapS.
>

Hi Ernest,

http://git.drbd.org/?p=drbd-8.0.git;a=commit;h=85b1963598cdb29d2e1066c0f4357c81558ff943

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :

Re: [Drbd-dev] Stuck in WFBitMapS again

[Philipp Reisner]

Am Mittwoch, 13. Februar 2008 00:55:51 schrieb Montrose, Ernest:
> It looks like we still have a race condition while finishing syncing and
> pausing/resuming syncing at the same time.
>
> What's happening is that we finish syncing.
> The secondary side goes to Connected at the end of
> drbd_resync_finished()
>
> The Primary side is still in drbd_resync_finished().  While still there,
>
> the syncer isp flag gets set and unset due to a higher priority device
> syncer getting paused/resumed.
>
> Now the Primary side sends "Inconsistent" state to the Secondary since
> we are still in drbd_resync_finished()
> and have not gone Connected and UptoDate yet. But the other side is
> connected and UpToDate though.
>
> The secondary goes WFBitMapS via drbd_sync_handshake()
>
> In the mean time the Primary finally goes Connected and UptoDate.
>
> The Secondary is stuck in WFBitMapS.
>
> I include a patch that may be the fix for this.  Any other ideas?
>
> Thanks.
> EM--


Hi Ernest,

I know it is quite some time now, but I had to remove this patch.
It breaks manual split brain resolution.
Commit ab7facf4e17d98558d2569ccf954f2c64eb7b650

That was the wrong way of fixing this.

Do you have something with logfiles of that event

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :

RE: [Drbd-dev] Stuck in WFBitMapS again

[Montrose, Ernest]

[-- Attachment #1: Type: text/plain, Size: 2252 bytes --]

Phil,
It's been a while here too.  I had put this on the back burner but I am
glad
you have some time to take a look at this. This has been a real sticky
problem for us.

We are seeing a couple of instances of this race condition.  In one case
we go WFBitMapS/WFBitMapT  and stay there.  In the other case we go
Connected/WFBitMapS. 

I include two sets of logs here.  In one log I had some instrumentations
when the problem happened so don't be confused by that. I hope these
help.

Thanks again.

EM--
-----Original Message-----
From: Philipp Reisner [mailto:philipp.reisner@linbit.com] 
Sent: Monday, March 31, 2008 10:44 AM
To: Montrose, Ernest
Cc: drbd-dev@linbit.com
Subject: Re: [Drbd-dev] Stuck in WFBitMapS again

Am Mittwoch, 13. Februar 2008 00:55:51 schrieb Montrose, Ernest:
> It looks like we still have a race condition while finishing syncing
and
> pausing/resuming syncing at the same time.
>
> What's happening is that we finish syncing.
> The secondary side goes to Connected at the end of
> drbd_resync_finished()
>
> The Primary side is still in drbd_resync_finished().  While still
there,
>
> the syncer isp flag gets set and unset due to a higher priority device
> syncer getting paused/resumed.
>
> Now the Primary side sends "Inconsistent" state to the Secondary since
> we are still in drbd_resync_finished()
> and have not gone Connected and UptoDate yet. But the other side is
> connected and UpToDate though.
>
> The secondary goes WFBitMapS via drbd_sync_handshake()
>
> In the mean time the Primary finally goes Connected and UptoDate.
>
> The Secondary is stuck in WFBitMapS.
>
> I include a patch that may be the fix for this.  Any other ideas?
>
> Thanks.
> EM--


Hi Ernest,

I know it is quite some time now, but I had to remove this patch.
It breaks manual split brain resolution.
Commit ab7facf4e17d98558d2569ccf954f2c64eb7b650

That was the wrong way of fixing this.

Do you have something with logfiles of that event

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :

[-- Attachment #2: drbdwfbitmap.txt --]
[-- Type: text/plain, Size: 12470 bytes --]

DRBD device gets stuck in WFBitMapS one side and WFBitMapT the other
====================================================================
Feb 24 23:48:34 node0 kernel: drbd27: conn( Unconnected -> WFConnection )
Feb 24 23:48:35 node0 kernel: drbd27: conn( WFConnection -> WFReportParams )
Feb 24 23:48:35 node0 kernel: drbd27: Handshake successful: DRBD Network Protocol version 86
Feb 24 23:48:35 node0 kernel: drbd27: Starting asender thread (from drbd27_receiver [25427])
Feb 24 23:48:35 node0 kernel: drbd27: peer( Unknown -> Secondary ) conn( WFReportParams -> Connected ) pdsk( DUnknown -> UpToDate )
Feb 24 23:48:35 node0 kernel: drbd27: Writing meta data super block now.
Feb 24 23:48:36 node0 kernel: drbd27: role( Secondary -> Primary )
Feb 24 23:48:36 node0 kernel: drbd27: Writing meta data super block now.
Feb 24 23:59:07 node0 kernel: drbd27: PingAck did not arrive in time.
Feb 24 23:59:07 node0 kernel: drbd27: peer( Secondary -> Unknown ) conn( Connected -> NetworkFailure ) pdsk( UpToDate -> DUnknown )
Feb 24 23:59:07 node0 kernel: drbd27: asender terminated
Feb 24 23:59:07 node0 kernel: drbd27: Terminating asender thread
Feb 24 23:59:07 node0 kernel: drbd27: Creating new current UUID
Feb 24 23:59:07 node0 kernel: drbd27: short read expecting header on sock: r=-512
Feb 24 23:59:07 node0 kernel: drbd27: tl_clear()
Feb 24 23:59:07 node0 kernel: drbd27: Connection closed
Feb 24 23:59:07 node0 kernel: drbd27: Writing meta data super block now.
Feb 24 23:59:07 node0 kernel: drbd27: conn( NetworkFailure -> Unconnected )
Feb 24 23:59:07 node0 kernel: drbd27: receiver terminated
Feb 24 23:59:07 node0 kernel: drbd27: receiver (re)started
Feb 24 23:59:07 node0 kernel: drbd27: conn( Unconnected -> WFConnection )
Feb 25 00:15:33 node0 kernel: drbd27: conn( WFConnection -> WFReportParams )
Feb 25 00:15:33 node0 kernel: drbd27: aftr_isp( 0 -> 1 )
Feb 25 00:15:33 node0 kernel: drbd27: aftr_isp( 1 -> 0 )
Feb 25 00:15:33 node0 kernel: drbd27: Handshake successful: DRBD Network Protocol version 86
Feb 25 00:15:33 node0 kernel: drbd27: Starting asender thread (from drbd27_receiver [25427])
Feb 25 00:15:33 node0 kernel: drbd27: peer( Unknown -> Secondary ) conn( WFReportParams -> WFBitMapS ) pdsk( DUnknown -> UpToDate )
Feb 25 00:15:33 node0 kernel: drbd27: Writing meta data super block now.
Feb 25 00:15:43 node0 kernel: drbd27: aftr_isp( 0 -> 1 )
Feb 25 00:15:43 node0 kernel: drbd27: peer_isp( 0 -> 1 )
Feb 25 00:15:43 node0 kernel: drbd27: aftr_isp( 1 -> 0 )
Feb 25 00:15:43 node0 kernel: drbd27: peer_isp( 1 -> 0 )

NODE1:
Feb 25 00:15:24 node1 kernel: drbd27: disk( Diskless -> Attaching )
Feb 25 00:15:24 node1 kernel: drbd27: Starting worker thread (from cqueue/0 [7665])
Feb 25 00:15:24 node1 kernel: drbd27: No usable activity log found.
Feb 25 00:15:24 node1 kernel: drbd27: max_segment_size ( = BIO size ) = 32768
Feb 25 00:15:24 node1 kernel: drbd27: drbd_bm_resize called with capacity == 12582456
Feb 25 00:15:24 node1 kernel: drbd27: resync bitmap: bits=1572807 words=49152
Feb 25 00:15:24 node1 kernel: drbd27: size = 6143 MB (6291228 KB)
Feb 25 00:15:24 node1 kernel: drbd27: reading of bitmap took 1 jiffies
Feb 25 00:15:24 node1 kernel: drbd27: recounting of set bits took additional 0 jiffies
Feb 25 00:15:24 node1 kernel: drbd27: 0 KB (0 bits) marked out-of-sync by on disk bit-map.
Feb 25 00:15:24 node1 kernel: drbd27: disk( Attaching -> UpToDate )
Feb 25 00:15:24 node1 kernel: drbd27: Writing meta data super block now.
Feb 25 00:15:24 node1 kernel: drbd27: conn( StandAlone -> Unconnected )
Feb 25 00:15:24 node1 kernel: drbd27: Starting receiver thread (from drbd27_worker [16484])
Feb 25 00:15:24 node1 kernel: drbd27: receiver (re)started
Feb 25 00:15:24 node1 kernel: drbd27: conn( Unconnected -> WFConnection )
Feb 25 00:15:34 node1 kernel: drbd27: aftr_isp( 0 -> 1 )
Feb 25 00:15:34 node1 kernel: drbd27: aftr_isp( 1 -> 0 )
Feb 25 00:15:34 node1 kernel: drbd27: Handshake successful: DRBD Network Protocol version 86
Feb 25 00:15:34 node1 kernel: drbd27: conn( WFConnection -> WFReportParams )
Feb 25 00:15:34 node1 kernel: drbd27: Starting asender thread (from drbd27_receiver [16491])
Feb 25 00:15:34 node1 kernel: drbd27: peer( Unknown -> Primary ) conn( WFReportParams -> Connected ) pdsk( DUnknown -> UpToDate ) peer_isp( 0 -> 1 )
Feb 25 00:15:34 node1 kernel: drbd27: Writing meta data super block now.
Feb 25 00:15:34 node1 kernel: drbd27: peer_isp( 1 -> 0 )
Feb 25 00:15:35 node1 kernel: drbd27: unexpected cstate (Connected) in receive_bitmap
Feb 25 00:15:35 node1 kernel: drbd27: conn( Connected -> WFBitMapT )
Feb 25 00:15:44 node1 kernel: drbd27: aftr_isp( 0 -> 1 )
Feb 25 00:15:44 node1 kernel: drbd27: peer_isp( 0 -> 1 )
Feb 25 00:15:45 node1 kernel: drbd27: aftr_isp( 1 -> 0 )
Feb 25 00:15:45 node1 kernel: drbd27: peer_isp( 1 -> 0 )




Still  another case getting Connected one side and WFBitMapS the other.
===========================================================================
NODE0:

Mar  5 22:31:59 node0 kernel: drbd5: conn( WFSyncUUID -> SyncTarget ) disk( UpToDate -> Inconsistent )
Mar  5 22:31:59 node0 kernel: drbd5: Began resync as SyncTarget (will sync 17628 KB [4407 bits set]).
Mar  5 22:31:59 node0 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:03 node0 kernel: drbd5: conn( SyncTarget -> PausedSyncT ) aftr_isp( 0 -> 1 )
Mar  5 22:32:03 node0 kernel: drbd5: Resync suspended
Mar  5 22:32:03 node0 kernel: drbd5: receive_state:EM--===== oconn(PausedSyncT) peer_state.conn(Connected) peer_state.disk(UpToDate) state.disk(Inconsistent)===
Mar  5 22:32:03 node0 kernel: drbd5: peer_isp( 0 -> 1 )
Mar  5 22:32:03 node0 kernel: drbd5: Resync done (total 1 sec; paused 0 sec; 17628 K/sec)
Mar  5 22:32:03 node0 kernel: drbd5:  uuid[Bitmap] now 98B2279CF244A665
Mar  5 22:32:03 node0 kernel: drbd5:  uuid[History_start] now F29410AEC0882498
Mar  5 22:32:03 node0 kernel: drbd5:  uuid[History_end] now 19FFEC1E2A6CCAAB
Mar  5 22:32:04 node0 kernel: drbd5:  uuid[History_start] now 98B2279CF244A665
Mar  5 22:32:04 node0 kernel: drbd5:  uuid[Bitmap] now 71E86A3E2A741DB6
Mar  5 22:32:04 node0 kernel: drbd5:  uuid[Current] now B392489356D183BC
Mar  5 22:32:04 node0 kernel: drbd5:  uuid[History_start] now 71E86A3E2A741DB6
Mar  5 22:32:04 node0 kernel: drbd5:  uuid[Bitmap] now 0000000000000000
Mar  5 22:32:04 node0 kernel: drbd5: conn( PausedSyncT -> Connected ) disk( Inconsistent -> UpToDate )
Mar  5 22:32:04 node0 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:05 node0 kernel: drbd5: receive_state:EM--===== oconn(Connected) peer_state.conn(WFBitMapS) peer_state.disk(UpToDate) state.disk(UpToDate)===
Mar  5 22:32:05 node0 kernel: drbd5: rct = 0 in /sandbox/emontros/devel/r1-ipod/platform/drbd/src/dist/BUILD/drbd-8.0.11/drbd/drbd_receiver.c:1937
Mar  5 22:32:05 node0 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:05 node0 kernel: drbd5: self B392489356D183BC:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:05 node0 kernel: drbd5: peer B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:05 node0 kernel: drbd5: uuid_compare()=0 by rule 4
Mar  5 22:32:05 node0 kernel: drbd5: unexpected cstate (Connected) in receive_bitmap
Mar  5 22:32:06 node0 kernel: drbd5: receive_state:EM--===== oconn(Connected) peer_state.conn(WFBitMapS) peer_state.disk(UpToDate) state.disk(UpToDate)===
Mar  5 22:32:06 node0 kernel: drbd5: rct = 0 in /sandbox/emontros/devel/r1-ipod/platform/drbd/src/dist/BUILD/drbd-8.0.11/drbd/drbd_receiver.c:1937
Mar  5 22:32:06 node0 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:06 node0 kernel: drbd5: self B392489356D183BC:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:06 node0 kernel: drbd5: peer B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:06 node0 kernel: drbd5: uuid_compare()=0 by rule 4
Mar  5 22:32:06 node0 kernel: drbd5: No resync, but 262127 bits in bitmap!
Mar  5 22:32:06 node0 kernel: drbd5: peer_isp( 1 -> 0 )
Mar  5 22:32:06 node0 kernel: drbd5: aftr_isp( 1 -> 0 )
Mar  5 22:32:07 node0 kernel: drbd5: receive_state:EM--===== oconn(Connected) peer_state.conn(WFBitMapS) peer_state.disk(UpToDate) state.disk(UpToDate)===
Mar  5 22:32:07 node0 kernel: drbd5: rct = 0 in /sandbox/emontros/devel/r1-ipod/platform/drbd/src/dist/BUILD/drbd-8.0.11/drbd/drbd_receiver.c:1937
Mar  5 22:32:07 node0 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:07 node0 kernel: drbd5: self B392489356D183BC:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:07 node0 kernel: drbd5: peer B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:07 node0 kernel: drbd5: uuid_compare()=0 by rule 4
Mar  5 22:32:08 node0 kernel: drbd5: No resync, but 262127 bits in bitmap!



NODE1:

Mar  5 22:32:09 node1 kernel: drbd5: conn( WFBitMapS -> SyncSource ) pdsk( UpToDate -> Inconsistent )
Mar  5 22:32:10 node1 kernel: drbd5: Began resync as SyncSource (will sync 17628 KB [4407 bits set]).
Mar  5 22:32:10 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:16 node1 kernel: drbd5: Resync done (total 1 sec; paused 0 sec; 17628 K/sec)
Mar  5 22:32:16 node1 kernel: drbd5:  uuid[History_start] now 71E86A3E2A741DB6
Mar  5 22:32:16 node1 kernel: drbd5:  uuid[Bitmap] now 0000000000000000
Mar  5 22:32:16 node1 kernel: drbd5: conn( SyncSource -> Connected ) pdsk( Inconsistent -> UpToDate )
Mar  5 22:32:16 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:16 node1 kernel: drbd5: aftr_isp( 0 -> 1 )
Mar  5 22:32:17 node1 kernel: drbd5: receive_state:EM--===== oconn(Connected) peer_state.conn(PausedSyncT) peer_state.disk(Inconsistent) state.disk(UpToDate)===
Mar  5 22:32:17 node1 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:17 node1 kernel: drbd5: self B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:17 node1 kernel: drbd5: peer 71E86A3E2A741DB6:0000000000000000:F29410AEC0882499:19FFEC1E2A6CCAAB
Mar  5 22:32:17 node1 kernel: drbd5: uuid_compare()=2 by rule 8
Mar  5 22:32:17 node1 kernel: drbd5: Becoming sync source due to disk states.
Mar  5 22:32:17 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:17 node1 kernel: drbd5: writing of bitmap took 0 jiffies
Mar  5 22:32:17 node1 kernel: drbd5: 1023 MB (262127 bits) marked out-of-sync by on disk bit-map.
Mar  5 22:32:17 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:17 node1 kernel: drbd5: conn( Connected -> WFBitMapS ) pdsk( UpToDate -> Inconsistent ) peer_isp( 0 -> 1 )
Mar  5 22:32:17 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:17 node1 kernel: drbd5: receive_state:EM--===== oconn(WFBitMapS) peer_state.conn(Connected) peer_state.disk(UpToDate) state.disk(UpToDate)===
Mar  5 22:32:17 node1 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:17 node1 kernel: drbd5: self B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:17 node1 kernel: drbd5: peer 71E86A3E2A741DB6:0000000000000000:F29410AEC0882499:19FFEC1E2A6CCAAB
Mar  5 22:32:18 node1 kernel: drbd5: uuid_compare()=2 by rule 8
Mar  5 22:32:18 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:18 node1 kernel: drbd5: writing of bitmap took 1 jiffies
Mar  5 22:32:18 node1 kernel: drbd5: 1023 MB (262127 bits) marked out-of-sync by on disk bit-map.
Mar  5 22:32:18 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:18 node1 kernel: drbd5: pdsk( Inconsistent -> UpToDate )
Mar  5 22:32:18 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:18 node1 kernel: drbd5: aftr_isp( 1 -> 0 )
Mar  5 22:32:18 node1 kernel: drbd5: receive_state:EM--===== oconn(WFBitMapS) peer_state.conn(Connected) peer_state.disk(UpToDate) state.disk(UpToDate)===
Mar  5 22:32:18 node1 kernel: drbd5: drbd_sync_handshake:
Mar  5 22:32:18 node1 kernel: drbd5: self B392489356D183BD:0000000000000000:71E86A3E2A741DB6:98B2279CF244A665
Mar  5 22:32:18 node1 kernel: drbd5: peer 71E86A3E2A741DB6:0000000000000000:F29410AEC0882499:19FFEC1E2A6CCAAB
Mar  5 22:32:18 node1 kernel: drbd5: uuid_compare()=2 by rule 8
Mar  5 22:32:18 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:18 node1 kernel: drbd5: writing of bitmap took 0 jiffies
Mar  5 22:32:18 node1 kernel: drbd5: 1023 MB (262127 bits) marked out-of-sync by on disk bit-map.
Mar  5 22:32:18 node1 kernel: drbd5: Writing meta data super block now.
Mar  5 22:32:18 node1 kernel: drbd5: peer_isp( 1 -> 0 )