[Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Graham, Simon]

I've been seeing a fairly reproducible crash in _drbd_send_page due to a
NULL page pointer; my working theory is that somehow the bio is being
freed whilst it is still in use and I think I have some evidence of this
now -- I modified drbd_send_page to print out info on the request in
progress when the error occurs and have the following trace:

drbd1: data >>> Data (sector 1560250, id e7f15e10, seq b75, f 0)
drbd1: meta <<< WriteAck (sector 1560250, size 1000, id e7f15e10, seq
b75)
drbd1: in got_BlockAck:2796: ap_pending_cnt = -1 < 0 !
drbd1: Sector 1560250, id e7f15e10, seq b75

drbd1: drbd_send_zc_bio - NULL Page; bio eb49d380, bvec c07678fc
drbd1:     sector: 1560250, block_id: e7f15e10, seq b75
 [<c0105081>] show_trace+0x21/0x30
 [<c01051be>] dump_stack+0x1e/0x20
 [<f1291400>] _drbd_send_zc_bio+0x100/0x140 [drbd]
 [<f1291582>] drbd_send_dblock+0x142/0x230 [drbd]
 [<f127f8a6>] w_send_dblock+0x36/0x260 [drbd]
 [<f1280b16>] drbd_worker+0x186/0x4f7 [drbd]
 [<f128ffdd>] drbd_thread_setup+0x7d/0xe0 [drbd]
 [<c0102d85>] kernel_thread_helper+0x5/0x10
Unable to handle kernel NULL pointer dereference at virtual address
00000000

The trace of send data happens before the data is actually sent, so it
would seem here that we received the Ack before we finished sending the
data!!!!!

I searched back, and the specific block_id was recently used for a
request on a different device (not surprising) and the previous data
message on the drbd1 device had sequence number b74 as expected.

You will also note that we hit the assert failure re ap_pending_cnt when
processing the ack -- I think this is because w_send_dblock doesn't
increment ap_pending_cnt until drbd_send_dblock returns successfully, so
it's probably at zero at the moment the Ack is received...

I'm still debugging but I thought it would be useful to post what I've
found in case anyone has any bright ideas...
/simgr

RE: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Graham, Simon]

Have now traced the network and I am very confused -- I'm still
convinced that the problem is that we are still in drbd_send_zc_bio when
the Ack for the write is received BUT the data is correctly and
completely sent on the wire to the peer who turns around and sends a
WriteAck to it.

I suppose it's theoretically possible that sending the final portion of
the data from drbd_send_zc_bio might end up being pended; maybe the pipe
is full when we go to send it which causes the worker thread to get
suspended. That being the case, it's possible that this thread doesn't
get rescheduled until waaaaay later - specifically, AFTER the Ack has
been received and the bio completed and freed -- now we return to the
worker thread and attempt to continue to loop through the (now free) bio
with __bio_for_each_segment -- does this seem feasible?

Assuming for the minute that this IS the cause, what would a suitable
solution be? We really need to delay processing the Ack until the
send-dblock/send-block has finished -- i.e. we should wait until the
RQ_DRBD_ON_WIRE flag is set in the request -- is there something
suitable we could issue a wait_event_interruptible() on in
got_BlockAck() to wait for this?

/simgr

> -----Original Message-----
> From: drbd-dev-bounces@linbit.com [mailto:drbd-dev-bounces@linbit.com]
> On Behalf Of Graham, Simon
> Sent: Tuesday, August 15, 2006 2:56 PM
> To: drbd-dev@linbit.com
> Subject: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page
> 
> I've been seeing a fairly reproducible crash in _drbd_send_page due to
> a
> NULL page pointer; my working theory is that somehow the bio is being
> freed whilst it is still in use and I think I have some evidence of
> this
> now -- I modified drbd_send_page to print out info on the request in
> progress when the error occurs and have the following trace:
> 
> drbd1: data >>> Data (sector 1560250, id e7f15e10, seq b75, f 0)
> drbd1: meta <<< WriteAck (sector 1560250, size 1000, id e7f15e10, seq
> b75)
> drbd1: in got_BlockAck:2796: ap_pending_cnt = -1 < 0 !
> drbd1: Sector 1560250, id e7f15e10, seq b75
> 
> drbd1: drbd_send_zc_bio - NULL Page; bio eb49d380, bvec c07678fc
> drbd1:     sector: 1560250, block_id: e7f15e10, seq b75
>  [<c0105081>] show_trace+0x21/0x30
>  [<c01051be>] dump_stack+0x1e/0x20
>  [<f1291400>] _drbd_send_zc_bio+0x100/0x140 [drbd]
>  [<f1291582>] drbd_send_dblock+0x142/0x230 [drbd]
>  [<f127f8a6>] w_send_dblock+0x36/0x260 [drbd]
>  [<f1280b16>] drbd_worker+0x186/0x4f7 [drbd]
>  [<f128ffdd>] drbd_thread_setup+0x7d/0xe0 [drbd]
>  [<c0102d85>] kernel_thread_helper+0x5/0x10
> Unable to handle kernel NULL pointer dereference at virtual address
> 00000000
> 
> The trace of send data happens before the data is actually sent, so it
> would seem here that we received the Ack before we finished sending
the
> data!!!!!
> 
> I searched back, and the specific block_id was recently used for a
> request on a different device (not surprising) and the previous data
> message on the drbd1 device had sequence number b74 as expected.
> 
> You will also note that we hit the assert failure re ap_pending_cnt
> when
> processing the ack -- I think this is because w_send_dblock doesn't
> increment ap_pending_cnt until drbd_send_dblock returns successfully,
> so
> it's probably at zero at the moment the Ack is received...
> 
> I'm still debugging but I thought it would be useful to post what I've
> found in case anyone has any bright ideas...
> /simgr
> 
> 
> _______________________________________________
> drbd-dev mailing list
> drbd-dev@lists.linbit.com
> http://lists.linbit.com/mailman/listinfo/drbd-dev

RE: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Graham, Simon]

Well, FWIW, I think my theory is correct -- I added an assert to
got_BlockAck that the ON_WIRE flag is set and it hit:

drbd1: data >>> Data (sector 12470, size ffffffe8, id e822dbe0, seq
10ea, f 0)
drbd1: meta <<< WriteAck (sector 12470, size 1000, id e822dbe0, seq
10ea)
drbd1: ASSERT( req->rq_status & RQ_DRBD_ON_WIRE ) in
/sandbox/sgraham/sn/trunk/platform/drbd/8.0/drbd/drbd_receiver.c:2785
drbd1: in got_BlockAck:2799: ap_pending_cnt = -1 < 0 !
drbd1: Sector 12470, id e822dbe0, seq 10ea

For example -- no crash in this case, but that's just dumb luck I think;
I know you guys are busy, but do you have any suggestions for the right
way to have got_BlockAck wait for the send thread to complete?

Simon

> -----Original Message-----
> From: Graham, Simon
> Sent: Tuesday, August 15, 2006 3:47 PM
> To: Graham, Simon; drbd-dev@linbit.com
> Subject: RE: [Drbd-dev] DRBD-8 - crash due to NULL page* in
> drbd_send_page
> 
> Have now traced the network and I am very confused -- I'm still
> convinced that the problem is that we are still in drbd_send_zc_bio
> when the Ack for the write is received BUT the data is correctly and
> completely sent on the wire to the peer who turns around and sends a
> WriteAck to it.
> 
> I suppose it's theoretically possible that sending the final portion
of
> the data from drbd_send_zc_bio might end up being pended; maybe the
> pipe is full when we go to send it which causes the worker thread to
> get suspended. That being the case, it's possible that this thread
> doesn't get rescheduled until waaaaay later - specifically, AFTER the
> Ack has been received and the bio completed and freed -- now we return
> to the worker thread and attempt to continue to loop through the (now
> free) bio with __bio_for_each_segment -- does this seem feasible?
> 
> Assuming for the minute that this IS the cause, what would a suitable
> solution be? We really need to delay processing the Ack until the
send-
> dblock/send-block has finished -- i.e. we should wait until the
> RQ_DRBD_ON_WIRE flag is set in the request -- is there something
> suitable we could issue a wait_event_interruptible() on in
> got_BlockAck() to wait for this?
> 
> /simgr
> 
> > -----Original Message-----
> > From: drbd-dev-bounces@linbit.com [mailto:drbd-dev-
> bounces@linbit.com]
> > On Behalf Of Graham, Simon
> > Sent: Tuesday, August 15, 2006 2:56 PM
> > To: drbd-dev@linbit.com
> > Subject: [Drbd-dev] DRBD-8 - crash due to NULL page* in
> drbd_send_page
> >
> > I've been seeing a fairly reproducible crash in _drbd_send_page due
> to
> > a
> > NULL page pointer; my working theory is that somehow the bio is
being
> > freed whilst it is still in use and I think I have some evidence of
> > this
> > now -- I modified drbd_send_page to print out info on the request in
> > progress when the error occurs and have the following trace:
> >
> > drbd1: data >>> Data (sector 1560250, id e7f15e10, seq b75, f 0)
> > drbd1: meta <<< WriteAck (sector 1560250, size 1000, id e7f15e10,
seq
> > b75)
> > drbd1: in got_BlockAck:2796: ap_pending_cnt = -1 < 0 !
> > drbd1: Sector 1560250, id e7f15e10, seq b75
> >
> > drbd1: drbd_send_zc_bio - NULL Page; bio eb49d380, bvec c07678fc
> > drbd1:     sector: 1560250, block_id: e7f15e10, seq b75
> >  [<c0105081>] show_trace+0x21/0x30
> >  [<c01051be>] dump_stack+0x1e/0x20
> >  [<f1291400>] _drbd_send_zc_bio+0x100/0x140 [drbd]
> >  [<f1291582>] drbd_send_dblock+0x142/0x230 [drbd]
> >  [<f127f8a6>] w_send_dblock+0x36/0x260 [drbd]
> >  [<f1280b16>] drbd_worker+0x186/0x4f7 [drbd]
> >  [<f128ffdd>] drbd_thread_setup+0x7d/0xe0 [drbd]
> >  [<c0102d85>] kernel_thread_helper+0x5/0x10
> > Unable to handle kernel NULL pointer dereference at virtual address
> > 00000000
> >
> > The trace of send data happens before the data is actually sent, so
> it
> > would seem here that we received the Ack before we finished sending
> the
> > data!!!!!
> >
> > I searched back, and the specific block_id was recently used for a
> > request on a different device (not surprising) and the previous data
> > message on the drbd1 device had sequence number b74 as expected.
> >
> > You will also note that we hit the assert failure re ap_pending_cnt
> > when
> > processing the ack -- I think this is because w_send_dblock doesn't
> > increment ap_pending_cnt until drbd_send_dblock returns
successfully,
> > so
> > it's probably at zero at the moment the Ack is received...
> >
> > I'm still debugging but I thought it would be useful to post what
> I've
> > found in case anyone has any bright ideas...
> > /simgr
> >
> >
> > _______________________________________________
> > drbd-dev mailing list
> > drbd-dev@lists.linbit.com
> > http://lists.linbit.com/mailman/listinfo/drbd-dev

Re: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Lars Ellenberg]

/ 2006-08-15 16:30:31 -0400
\ Graham, Simon:
> Well, FWIW, I think my theory is correct -- I added an assert to
> got_BlockAck that the ON_WIRE flag is set and it hit:
> 
> drbd1: data >>> Data (sector 12470, size ffffffe8, id e822dbe0, seq
> 10ea, f 0)
> drbd1: meta <<< WriteAck (sector 12470, size 1000, id e822dbe0, seq
> 10ea)
> drbd1: ASSERT( req->rq_status & RQ_DRBD_ON_WIRE ) in
> /sandbox/sgraham/sn/trunk/platform/drbd/8.0/drbd/drbd_receiver.c:2785
> drbd1: in got_BlockAck:2799: ap_pending_cnt = -1 < 0 !
> drbd1: Sector 12470, id e822dbe0, seq 10ea
> 
> For example -- no crash in this case, but that's just dumb luck I think;

Yes we seemingly have race there. I already stumbled upon it myself but
got distracted by other problems.  We had a similar race there long ago,
and fixed it.  But probably it got reintroduced when we switched to
"send from worker context", where we also introduce this dubious
"on wire" flag.

But I don't really think that is the problem for that NULL pointer.
There is something else going on here, see below.
Just for debugging: could you try switching that zero copy off,
and use the copy-on-send?

or define our DRBD_MAX_SEGMENT_SIZE to be 4k instead of 32k,
to see if that makes a difference.
 (either HT_SHIFT 3, or assign PAGE_SIZE to q->max_segment_size and
other where appropriate. looking at that code, I think we might
have some corner case bugs stacking q parameters, still; brrgs)

> I know you guys are busy, but do you have any suggestions for the right
> way to have got_BlockAck wait for the send thread to complete?

in fact, we have had a public holiday today here...

but I don't get it.
the WriteAck is sent by the peer after it successfully received the
data, read it into some pages attached to some bio, submitted this bio,
and got a completion event from disk...
this WriteAck simply _cannot_ be received before the data is
successfully transmitted, so the _drbd_send_zc_bio has long finished.

so if you see NULL pages there, we have an invalid bio.

how is your test setup this time?

in my test setup, during "normal operation", i.e. no resync running,
network link stable etc., just application requests, I can write
gigabytes in a loop for hours and not trigger anything unusual.
this is on dual opteron preemtible smp with not-too-slow disk and
gigabit ethernet.

the problems I see are broken cleanup during connection loss,
some lately (re)introduced (probably harmless but annoying) races
during resync with concurrent application writes, and unpleasant
suprises when we try to handle disk failures.

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

RE: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Graham, Simon]

Thanks for the update (and for responding when you are supposed to be on
holiday!)

> But I don't really think that is the problem for that NULL pointer.
> There is something else going on here, see below.
> Just for debugging: could you try switching that zero copy off,
> and use the copy-on-send?
> 

I'll give that a go tomorrow.

> 
> but I don't get it.
> the WriteAck is sent by the peer after it successfully received the
> data, read it into some pages attached to some bio, submitted this
bio,
> and got a completion event from disk...
> this WriteAck simply _cannot_ be received before the data is
> successfully transmitted, so the _drbd_send_zc_bio has long finished.
> 

Well, I would have thought so to BUT I can see a way it could happen if
the system is very busy (which it is) -- I think that drbd_send_zc_bio
gets to the point of sending the very last bvec and passes the data to
TCP which pends because of some resource issue (such as the send window
being full) -- the data is then sent (I'm guessing) from the context of
whatever interrupt that makes the resource available and the worker
thread is made ready to run but never actually gets to run before the
Ack arrives from the other box (which is NOT particularly busy).

The only real evidence I have is the trace and the fact that I hit the
assert that the on-wire flag should be set. If we look closely at the
first trace, we see:

> > drbd1: data >>> Data (sector 1560250, id e7f15e10, seq b75, f 0)

(this is just before w_send_dblock sends the data)

> > drbd1: meta <<< WriteAck (sector 1560250, size 1000, id e7f15e10,
seq
> > b75)

(here's the ack for that sector)

> > drbd1: in got_BlockAck:2796: ap_pending_cnt = -1 < 0 !
> > drbd1: Sector 1560250, id e7f15e10, seq b75
> >

and we assert that the pending count went -ve

> > drbd1: drbd_send_zc_bio - NULL Page; bio eb49d380, bvec c07678fc
> > drbd1:     sector: 1560250, block_id: e7f15e10, seq b75

And here we are in drbd_send_zc_bio for the same sector, same block id,
same sequence number, so I think we're still in the call that started
where the original Data trace was output.

If you add to that the fact that this explains the assert failure on
ap_pending_cnt _and_ my new assert on the on-wire flag, it seems to me
to be fairly convincing that somehow we get the Ack before the send_zc
call has finished looping through the bvec's in the bio...

All I can do is quote the old adage - 'where there's a window there's a
bug' ;-)

> so if you see NULL pages there, we have an invalid bio.

BTW - sometimes, I don't hit the test for NULL, I just crash on a
completely bogus pointer value -- this smacks of the bio being freed
while we are still referencing it.

> 
> how is your test setup this time?
> 

So, I'm running four DRBD volumes, three of them in use by apps running
stress (which use large amounts of CPU) and one lightly used for logging
info. There is no resync in progress, just the test stress. The systems
are DP Dell boxes with a dedicated gbit link used by DRBD traffic.

> 
> the problems I see are broken cleanup during connection loss,
> some lately (re)introduced (probably harmless but annoying) races
> during resync with concurrent application writes, and unpleasant
> suprises when we try to handle disk failures.
> 

Yah -- I'm trying to get back to my work on handling the disk failures
(removing panics in particular) but I need a stable base for this.

Simon

Re: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Philipp Reisner]

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

Am Dienstag, 15. August 2006 21:46 schrieb Graham, Simon:
> Have now traced the network and I am very confused -- I'm still
> convinced that the problem is that we are still in drbd_send_zc_bio when
> the Ack for the write is received BUT the data is correctly and
> completely sent on the wire to the peer who turns around and sends a
> WriteAck to it.
>
> I suppose it's theoretically possible that sending the final portion of
> the data from drbd_send_zc_bio might end up being pended; maybe the pipe
> is full when we go to send it which causes the worker thread to get
> suspended. That being the case, it's possible that this thread doesn't
> get rescheduled until waaaaay later - specifically, AFTER the Ack has
> been received and the bio completed and freed -- now we return to the
> worker thread and attempt to continue to loop through the (now free) bio
> with __bio_for_each_segment -- does this seem feasible?
>
> Assuming for the minute that this IS the cause, what would a suitable
> solution be? We really need to delay processing the Ack until the
> send-dblock/send-block has finished -- i.e. we should wait until the
> RQ_DRBD_ON_WIRE flag is set in the request -- is there something
> suitable we could issue a wait_event_interruptible() on in
> got_BlockAck() to wait for this?
>

Simon, 

I think a suitable solution would be to complete the request after
1) it was written locally.
2) the ack was received.
3) and we finished sending it [new]

I attached the patch. I guess you will rerun your tests with this
patch. [ it is completely untested ]

I take from Lars' mail yesterday that he could not reproduce this
problem here on our main test cluster here, so it is up to you
to verify it.

-philipp
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria    http://www.linbit.com :

[-- Attachment #2: for_simon.diff --]
[-- Type: text/x-diff, Size: 1275 bytes --]

Index: drbd_worker.c
===================================================================
--- drbd_worker.c	(revision 2373)
+++ drbd_worker.c	(working copy)
@@ -564,12 +564,10 @@
 
 	ok = drbd_send_dblock(mdev,req);
 	if (ok) {
-		spin_lock_irq(&mdev->req_lock);
-		req->rq_status |= RQ_DRBD_ON_WIRE;
-		spin_unlock_irq(&mdev->req_lock);
-
 		inc_ap_pending(mdev);
 
+		drbd_end_req(req,RQ_DRBD_ON_WIRE,1,drbd_req_get_sector(req));
+
 		if(mdev->net_conf->wire_protocol == DRBD_PROT_A) {
 			dec_ap_pending(mdev);
 			drbd_end_req(req, RQ_DRBD_SENT, 1, 
Index: drbd_int.h
===================================================================
--- drbd_int.h	(revision 2373)
+++ drbd_int.h	(working copy)
@@ -233,9 +233,9 @@
 #define RQ_DRBD_NOTHING	  0x0001
 #define RQ_DRBD_SENT      0x0010   // We got an ack
 #define RQ_DRBD_LOCAL     0x0020   // We wrote it to the local disk
-#define RQ_DRBD_DONE      0x0030   // We are done ;)
 #define RQ_DRBD_IN_TL     0x0040   // Set when it is in the TL
 #define RQ_DRBD_ON_WIRE   0x0080   // Set as soon as it is on the socket...
+#define RQ_DRBD_DONE      ( RQ_DRBD_SENT + RQ_DRBD_LOCAL + RQ_DRBD_ON_WIRE )
 
 /* drbd_meta-data.c (still in drbd_main.c) */
 #define DRBD_MD_MAGIC (DRBD_MAGIC+4) // 4th incarnation of the disk layout.

Re: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Philipp Reisner]

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


> > Assuming for the minute that this IS the cause, what would a suitable
> > solution be? We really need to delay processing the Ack until the
> > send-dblock/send-block has finished -- i.e. we should wait until the
> > RQ_DRBD_ON_WIRE flag is set in the request -- is there something
> > suitable we could issue a wait_event_interruptible() on in
> > got_BlockAck() to wait for this?
[...]
> I attached the patch. I guess you will rerun your tests with this
> patch. [ it is completely untested ]
>

And the second version of that patch...

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

[-- Attachment #2: for_simon2.diff --]
[-- Type: text/x-diff, Size: 1692 bytes --]

Index: drbd_worker.c
===================================================================
--- drbd_worker.c	(revision 2373)
+++ drbd_worker.c	(working copy)
@@ -564,12 +564,10 @@
 
 	ok = drbd_send_dblock(mdev,req);
 	if (ok) {
-		spin_lock_irq(&mdev->req_lock);
-		req->rq_status |= RQ_DRBD_ON_WIRE;
-		spin_unlock_irq(&mdev->req_lock);
-
 		inc_ap_pending(mdev);
 
+		drbd_end_req(req,RQ_DRBD_ON_WIRE,1,drbd_req_get_sector(req));
+
 		if(mdev->net_conf->wire_protocol == DRBD_PROT_A) {
 			dec_ap_pending(mdev);
 			drbd_end_req(req, RQ_DRBD_SENT, 1, 
Index: drbd_req.c
===================================================================
--- drbd_req.c	(revision 2373)
+++ drbd_req.c	(working copy)
@@ -341,7 +341,7 @@
 	if (!local)
 		req->rq_status |= RQ_DRBD_LOCAL;
 	if (!remote)
-		req->rq_status |= RQ_DRBD_SENT;
+		req->rq_status |= RQ_DRBD_SENT | RQ_DRBD_ON_WIRE;
 
 	/* we need to plug ALWAYS since we possibly need to kick lo_dev */
 	drbd_plug_device(mdev);
Index: drbd_int.h
===================================================================
--- drbd_int.h	(revision 2373)
+++ drbd_int.h	(working copy)
@@ -233,9 +233,9 @@
 #define RQ_DRBD_NOTHING	  0x0001
 #define RQ_DRBD_SENT      0x0010   // We got an ack
 #define RQ_DRBD_LOCAL     0x0020   // We wrote it to the local disk
-#define RQ_DRBD_DONE      0x0030   // We are done ;)
 #define RQ_DRBD_IN_TL     0x0040   // Set when it is in the TL
 #define RQ_DRBD_ON_WIRE   0x0080   // Set as soon as it is on the socket...
+#define RQ_DRBD_DONE      ( RQ_DRBD_SENT + RQ_DRBD_LOCAL + RQ_DRBD_ON_WIRE )
 
 /* drbd_meta-data.c (still in drbd_main.c) */
 #define DRBD_MD_MAGIC (DRBD_MAGIC+4) // 4th incarnation of the disk layout.

RE: [Drbd-dev] DRBD-8 - crash due to NULL page* in drbd_send_page

[Graham, Simon]

> > > RQ_DRBD_ON_WIRE flag is set in the request -- is there something
> > > suitable we could issue a wait_event_interruptible() on in
> > > got_BlockAck() to wait for this?
> [...]
> > I attached the patch. I guess you will rerun your tests with this
> > patch. [ it is completely untested ]
> >
> 
> And the second version of that patch...
> 

I like it -- simple and elegant; wish I'd thought of it!

I just tried this and it's spot on - no crash plus, to be sure, I added
some trace in drbd_end_req to print the stack if it is called with the
on-wire flag set and this actually completes the request - here's a
sample of the output (and note how much goes on between the time the ack
is received and the time the request is finally completed from the
worker context - I wonder if the fact that a different socket is used
for the ack might also contribute to the odd timing):

drbd1: data >>> Data (sector 12618, size 8000, id e81b8f28, seq 766b1, f
0)	<<< started send data for drbd1/12618
drbd1: meta <<< WriteAck (sector 125b8, size 8000, id e81b8208, seq
1298)
drbd1: meta <<< WriteAck (sector 125f8, size 3000, id ec1cae48, seq
1299)
drbd1: meta <<< WriteAck (sector 12610, size 1000, id e81b8cf8, seq
129a)
drbd0: data >>> Data (sector 129d0, size 3000, id e81b8ba8, seq 142f, f
0)	<<< started send data for drbd0/129d0
drbd0: meta <<< WriteAck (sector 129b8, size 3000, id e81b8da0, seq
142e)
drbd2: meta >>> WriteAck (sector 11af8, size 8000, id ea5acc88, seq
767f3)
drbd2: meta >>> WriteAck (sector 11b38, size 3000, id ea5aca90, seq
767f4)
drbd2: meta >>> WriteAck (sector 11b50, size 1000, id ea5ac320, seq
767f5)
drbd2: meta >>> WriteAck (sector 11b58, size 8000, id ea5acbe0, seq
767f6)
drbd2: meta >>> WriteAck (sector 11b98, size 3000, id ea5ac128, seq
767f7)
drbd2: meta >>> WriteAck (sector 11bb0, size 8000, id ea5ace80, seq
767f8)
drbd2: meta >>> WriteAck (sector 11bf0, size 3000, id ea5ac588, seq
767f9)
drbd2: meta >>> WriteAck (sector 11c08, size 3000, id ea5ac898, seq
767fa)
drbd2: data <<< UnplugRemote (7)
drbd0: meta <<< WriteAck (sector 129d0, size 3000, id e81b8ba8, seq
142f)	<<< received Ack for drbd0/129d0
drbd0: ASSERT( req->rq_status & RQ_DRBD_ON_WIRE ) in
/sandbox/sgraham/sn/trunk/platform/drbd/8.0/drbd/drbd_receiver.c:2785
drbd0: in got_BlockAck:2799: ap_pending_cnt = -1 < 0 !
drbd0: Sector 129d0, id e81b8ba8, seq 142f
drbd1: meta <<< WriteAck (sector 12618, size 8000, id e81b8f28, seq
129b)	<<< received Ack for drbd1/12618
drbd1: ASSERT( req->rq_status & RQ_DRBD_ON_WIRE ) in
/sandbox/sgraham/sn/trunk/platform/drbd/8.0/drbd/drbd_receiver.c:2785
drbd1: in got_BlockAck:2799: ap_pending_cnt = -1 < 0 !
drbd1: Sector 12618, id e81b8f28, seq 129b
drbd2: data <<< Data (sector 3f1b0000300763ec, size 1000, id ea5ac898,
seq 1409, f 0)
drbd2: meta >>> WriteAck (sector 11c20, size 1000, id ea5ac898, seq
767fb)
drbd2: data <<< Barrier (barrier 0)
drbd2: meta >>> BarrierAck (barrier 6976)
drbd2: data <<< Data (sector 401b0000300763ec, size 1000, id ea5ac898,
seq 140a, f 0)
drbd2: data <<< UnplugRemote (7)
drbd0: Request completed from send - Ack must have arrived early
<<< finally finished sending drbd0/129d0
 [<c0105081>] show_trace+0x21/0x30
 [<c01051be>] dump_stack+0x1e/0x20
 [<f128900d>] drbd_end_req+0x2fd/0x570 [drbd]
 [<f127f999>] w_send_dblock+0x129/0x280 [drbd]
 [<f1280b36>] drbd_worker+0x186/0x4f7 [drbd]
 [<f129006d>] drbd_thread_setup+0x7d/0xe0 [drbd]
 [<c0102d85>] kernel_thread_helper+0x5/0x10
drbd0: data >>> UnplugRemote (7)
drbd0: data >>> Barrier (barrier 4882)
drbd0: meta <<< BarrierAck (barrier 4882)
drbd1: Request completed from send - Ack must have arrived early
<<< finally finished drbd1/12618
 [<c0105081>] show_trace+0x21/0x30
 [<c01051be>] dump_stack+0x1e/0x20
 [<f128900d>] drbd_end_req+0x2fd/0x570 [drbd]
 [<f127f999>] w_send_dblock+0x129/0x280 [drbd]
 [<f1280b36>] drbd_worker+0x186/0x4f7 [drbd]
 [<f129006d>] drbd_thread_setup+0x7d/0xe0 [drbd]
 [<c0102d85>] kernel_thread_helper+0x5/0x10

Thanks for the fix!
Simon