Re: Issue #5876 : assertion failure in rbd_img_obj_callback()

[Alex Elder <elder@ieee.org>]

OK, here's some more analysis of this one.  I'm pretty
convinced the object request in question has already
been freed/destroyed.  The real question is "why?"

On 03/25/2014 05:17 PM, Olivier Bonvalet wrote:
> Mar 25 23:14:45 rurkh kernel: [  330.054196] rbd_img_obj_callback: bad image object request information:
> Mar 25 23:14:45 rurkh kernel: [  330.054205] obj_request ffff88025f3df058
> Mar 25 23:14:45 rurkh kernel: [  330.054209]     ->object_name <(null)>
This can occur for an object request that has been destroyed.
After the name is freed, the field is set to NULL.

> Mar 25 23:14:45 rurkh kernel: [  330.054211]     ->offset 0
> Mar 25 23:14:45 rurkh kernel: [  330.054213]     ->length 4096
Given the image request, this makes sense as the second of
two object request in this image request.  (More on the offsets
below).

> Mar 25 23:14:45 rurkh kernel: [  330.054216]     ->type 0x1
This is OBJ_REQUEST_BIO.  Reasonable.

> Mar 25 23:14:45 rurkh kernel: [  330.054218]     ->flags 0x3
This means IMG_DATA and DONE are set.  It's an image object
(which is expected), and it's done (which is also expected,
because we're calling the callback function).

> Mar 25 23:14:45 rurkh kernel: [  330.054220]     ->which 4294967295
This is BAD_WHICH.  That value overwrites the original when
an image object request is removed from its image in
rbd_img_obj_request_del().

> Mar 25 23:14:45 rurkh kernel: [  330.054222]     ->xferred 4096
> Mar 25 23:14:45 rurkh kernel: [  330.054224]     ->result 0
> Mar 25 23:14:45 rurkh kernel: [  330.054227] img_request ffff8802731f8448
> Mar 25 23:14:45 rurkh kernel: [  330.054229]     ->snap 0xfffffffffffffffe
This is CEPH_NOSNAP.

> Mar 25 23:14:45 rurkh kernel: [  330.054231]     ->offset 2508181504
> Mar 25 23:14:45 rurkh kernel: [  330.054233]     ->length 16384
Offset is 0x957FD000, length 0x4000,  The first object request
should be (assuming 4MB objects) object 255, offset 0x3FD000,
length 0x3000 (or 12KB)  The second object request should be in
object 256, offset 0, length 0x1000 (or 4KB).

> Mar 25 23:14:45 rurkh kernel: [  330.054235]     ->flags 0x0
It is not layered nor initiated by a child image.  It was a read.

> Mar 25 23:14:45 rurkh kernel: [  330.054237]     ->obj_request_count 0
As objects are removed from an image request, the request count
is decremented until it's zero.  This suggests this image request
(which looks for the most part valid) has been destroyed (or at
least is in the process).

> Mar 25 23:14:45 rurkh kernel: [  330.054239]     ->next_completion 2
For an image request comprised of 2 object requests, this is
the right value when both of the object requests have completed.
The next completion (which will never occur) equals the object
request count (2).

> Mar 25 23:14:45 rurkh kernel: [  330.054241]     ->xferred 16384
This means the request transferred completely...

> Mar 25 23:14:45 rurkh kernel: [  330.054243]     ->result 0
...and was successful.


So, it looks like the image request completed successfully.  The
first and second object requests must have both passed through
rbd_img_obj_callback() in order for this to occur, and both of
them transferred all their data successfully.

However, at the time of this assertion failure, the callback
is being called for the already-completed second object
request.  Why?

The only place an object request's callback is called is in
rbd_obj_request_complete().  Olivier reports that these are
version 1 images and there is no layering involved.  So the
only place rbd_obj_request_complete() is called is from
rbd_osd_req_callback(), and then only if the object request
has been marked done by (in this case) rbd_osd_read_callback().
For a non-layered image object request, that always occurs
(after possibly zeroing all or part of the buffer).  So it
makes sense that these OSD read requests completed normally,
and triggered object request completion, and when both of
them had completed they caused the image request to complete.

This suggests that rbd_osd_req_callback() got called more
than once for that second object request.  That function is
called only via ceph_osd_request->r_callback(), and that
only occurs in net/ceph/osd_client.c:handle_reply().  It
only calls it if local variable already_completed is false.
That's set to the osd request's r_got_reply value, taken
while the OSD client' request mutex is held.

Any chance the osd client can be calling r_callback twice?

A second possibility is that the last object request
got duplicated somehow.  Right now I'm looking at
rbd_img_request_fill() and bio_chain_clone_range() to
see if I can see a way that could happen.

That's it for now.  I'm pretty sure this is getting
pretty close to the root cause.

					-Alex