Issue #5876 : assertion failure in rbd_img_obj_callback()

Issue #5876 : assertion failure in rbd_img_obj_callback()

[Olivier Bonvalet]

Hi,

what can/should I do to help fix that problem ?

for now, RBD kernel client hang on : 
        Assertion failure in rbd_img_obj_callback() at line 2131:
           rbd_assert(which >= img_request->next_completion);

or on :
        Assertion failure in rbd_img_obj_callback() at line 2127:
            rbd_assert(img_request != NULL);


I have both case at least once per week, on latest 3.13.5 kernels.

It seems that the problem occurs only on more loaded servers (I have 4
near same servers, and crash occurs on two of them. If I move the VM,
crash follows...).

Olivier

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> Hi,
>
> what can/should I do to help fix that problem ?
>
> for now, RBD kernel client hang on :
>         Assertion failure in rbd_img_obj_callback() at line 2131:
>            rbd_assert(which >= img_request->next_completion);
>
> or on :
>         Assertion failure in rbd_img_obj_callback() at line 2127:
>             rbd_assert(img_request != NULL);
>
>
> I have both case at least once per week, on latest 3.13.5 kernels.
>
> It seems that the problem occurs only on more loaded servers (I have 4
> near same servers, and crash occurs on two of them. If I move the VM,
> crash follows...).

Hi,

I'm looking into this, but it doesn't reproduce on my boxes.  This must
be some sort of race and the fact that there is nothing else in the
dmesg right before the splats doesn't help.

Can you send me your 3.13.5 rbd.ko and libceph.ko?  Also, just so
I know, can you build your own kernel?

Thanks,

                Ilya

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 11:20 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>
> Le mardi 25 mars 2014 à 11:04 +0200, Ilya Dryomov a écrit :
>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>> > Hi,
>> >
>> > what can/should I do to help fix that problem ?
>> >
>> > for now, RBD kernel client hang on :
>> >         Assertion failure in rbd_img_obj_callback() at line 2131:
>> >            rbd_assert(which >= img_request->next_completion);
>> >
>> > or on :
>> >         Assertion failure in rbd_img_obj_callback() at line 2127:
>> >             rbd_assert(img_request != NULL);
>> >
>> >
>> > I have both case at least once per week, on latest 3.13.5 kernels.
>> >
>> > It seems that the problem occurs only on more loaded servers (I have 4
>> > near same servers, and crash occurs on two of them. If I move the VM,
>> > crash follows...).
>>
>> Hi,
>>
>> I'm looking into this, but it doesn't reproduce on my boxes.  This must
>> be some sort of race and the fact that there is nothing else in the
>> dmesg right before the splats doesn't help.
>>
>> Can you send me your 3.13.5 rbd.ko and libceph.ko?  Also, just so
>> I know, can you build your own kernel?
>>
>> Thanks,
>>
>>                 Ilya
>>
>
> Thanks for your help. Yes, logs are not very usefull here :( Maybe can I
> enable some debugging informations ?
>
> I add libceph.ko and rbd.ko in attachment. And yes, I can patch and
> build my own kernel. I also add the config file used to compile my
> current kernel, if it can help.

That's great, I'll keep that in mind.  Our debug mode is probably waay
too verbose for running it under load on the order of days so for now
I'll try to make as much sense as I can from the .ko and dumps and keep
digging.

Thanks,

                Ilya
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>> Hi,
>>
>> what can/should I do to help fix that problem ?
>>
>> for now, RBD kernel client hang on :
>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>            rbd_assert(which >= img_request->next_completion);

If you can build your own kernel as Ilya says I'd like to
see the values of which and img_request->next_completion
here.

If you can't, is there anything interesting about your
workload that might help reproduce the problem?

Thanks.

					-Alex

>>
>> or on :
>>         Assertion failure in rbd_img_obj_callback() at line 2127:
>>             rbd_assert(img_request != NULL);
>>
>>
>> I have both case at least once per week, on latest 3.13.5 kernels.
>>
>> It seems that the problem occurs only on more loaded servers (I have 4
>> near same servers, and crash occurs on two of them. If I move the VM,
>> crash follows...).
> 
> Hi,
> 
> I'm looking into this, but it doesn't reproduce on my boxes.  This must
> be some sort of race and the fact that there is nothing else in the
> dmesg right before the splats doesn't help.
> 
> Can you send me your 3.13.5 rbd.ko and libceph.ko?  Also, just so
> I know, can you build your own kernel?
> 
> Thanks,
> 
>                 Ilya
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

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

[Ilya Dryomov]

> On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>>> Hi,
>>>
>>> what can/should I do to help fix that problem ?
>>>
>>> for now, RBD kernel client hang on :
>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>            rbd_assert(which >= img_request->next_completion);
>
> If you can build your own kernel as Ilya says I'd like to
> see the values of which and img_request->next_completion
> here.

Looks like which was 1, which means that next_completion had to be 2 or
greater.  I miss solaris crash dumps ...

On a different note, why are we asserting next_completion outside of
a spinlock which is supposed to protect next_completion?

Thanks,

                Ilya

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

[Alex Elder]

On 03/25/2014 07:34 AM, Ilya Dryomov wrote:
>> On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
>>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>>>> Hi,
>>>>
>>>> what can/should I do to help fix that problem ?
>>>>
>>>> for now, RBD kernel client hang on :
>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>>            rbd_assert(which >= img_request->next_completion);
>>
>> If you can build your own kernel as Ilya says I'd like to
>> see the values of which and img_request->next_completion
>> here.
> 
> Looks like which was 1, which means that next_completion had to be 2 or
> greater.  I miss solaris crash dumps ...
> 
> On a different note, why are we asserting next_completion outside of
> a spinlock which is supposed to protect next_completion?

That's a very good point (which could be easily remedied by moving
the assertion down a couple lines).  The image object request (#1)
in this case will have been marked done at this point; it's possible
that request #2 (or later) was concurrently getting handled by the
for_each_obj_request_from() loop below in that same function, but
may not have updated next_completion yet.

So that *could* explain the tripped assertion.  The assertion
should be moved in any case, it's a bug.

That being said, it doesn't explain the other assertion:
        rbd_assert(img_request != NULL);
So there's at least one other thing going on.

					-Alex

> Thanks,
> 
>                 Ilya
> 

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 2:51 PM, Alex Elder <elder@ieee.org> wrote:
> On 03/25/2014 07:34 AM, Ilya Dryomov wrote:
>>> On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
>>>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>>>>> Hi,
>>>>>
>>>>> what can/should I do to help fix that problem ?
>>>>>
>>>>> for now, RBD kernel client hang on :
>>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>>>            rbd_assert(which >= img_request->next_completion);
>>>
>>> If you can build your own kernel as Ilya says I'd like to
>>> see the values of which and img_request->next_completion
>>> here.
>>
>> Looks like which was 1, which means that next_completion had to be 2 or
>> greater.  I miss solaris crash dumps ...
>>
>> On a different note, why are we asserting next_completion outside of
>> a spinlock which is supposed to protect next_completion?
>
> That's a very good point (which could be easily remedied by moving
> the assertion down a couple lines).  The image object request (#1)
> in this case will have been marked done at this point; it's possible
> that request #2 (or later) was concurrently getting handled by the
> for_each_obj_request_from() loop below in that same function, but
> may not have updated next_completion yet.
>
> So that *could* explain the tripped assertion.  The assertion
> should be moved in any case, it's a bug.
>
> That being said, it doesn't explain the other assertion:
>         rbd_assert(img_request != NULL);
> So there's at least one other thing going on.

Yeah, exactly my thoughts.

Thanks,

                Ilya

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 14:57 +0200, Ilya Dryomov a écrit :
> On Tue, Mar 25, 2014 at 2:51 PM, Alex Elder <elder@ieee.org> wrote:
> > On 03/25/2014 07:34 AM, Ilya Dryomov wrote:
> >>> On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
> >>>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> >>>>> Hi,
> >>>>>
> >>>>> what can/should I do to help fix that problem ?
> >>>>>
> >>>>> for now, RBD kernel client hang on :
> >>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
> >>>>>            rbd_assert(which >= img_request->next_completion);
> >>>
> >>> If you can build your own kernel as Ilya says I'd like to
> >>> see the values of which and img_request->next_completion
> >>> here.
> >>
> >> Looks like which was 1, which means that next_completion had to be 2 or
> >> greater.  I miss solaris crash dumps ...
> >>
> >> On a different note, why are we asserting next_completion outside of
> >> a spinlock which is supposed to protect next_completion?
> >
> > That's a very good point (which could be easily remedied by moving
> > the assertion down a couple lines).  The image object request (#1)
> > in this case will have been marked done at this point; it's possible
> > that request #2 (or later) was concurrently getting handled by the
> > for_each_obj_request_from() loop below in that same function, but
> > may not have updated next_completion yet.
> >
> > So that *could* explain the tripped assertion.  The assertion
> > should be moved in any case, it's a bug.
> >
> > That being said, it doesn't explain the other assertion:
> >         rbd_assert(img_request != NULL);
> > So there's at least one other thing going on.
> 
> Yeah, exactly my thoughts.
> 
> Thanks,
> 
>                 Ilya

So, a (partial) fix can be this patch ?

--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2123,6 +2123,7 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
        rbd_assert(obj_request_img_data_test(obj_request));
        img_request = obj_request->img_request;
 
+       spin_lock_irq(&img_request->completion_lock);
        dout("%s: img %p obj %p\n", __func__, img_request, obj_request);
        rbd_assert(img_request != NULL);
        rbd_assert(img_request->obj_request_count > 0);
@@ -2130,7 +2131,6 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
        rbd_assert(which < img_request->obj_request_count);
        rbd_assert(which >= img_request->next_completion);
 
-       spin_lock_irq(&img_request->completion_lock);
        if (which != img_request->next_completion)
                goto out;
 


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 08:18 AM, Olivier Bonvalet wrote:
> 
> 
> Le mardi 25 mars 2014 à 14:57 +0200, Ilya Dryomov a écrit :
>> On Tue, Mar 25, 2014 at 2:51 PM, Alex Elder <elder@ieee.org> wrote:
>>> On 03/25/2014 07:34 AM, Ilya Dryomov wrote:
>>>>> On 03/25/2014 04:04 AM, Ilya Dryomov wrote:
>>>>>> On Tue, Mar 25, 2014 at 10:39 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>>>>>>> Hi,
>>>>>>>
>>>>>>> what can/should I do to help fix that problem ?
>>>>>>>
>>>>>>> for now, RBD kernel client hang on :
>>>>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>>>>>            rbd_assert(which >= img_request->next_completion);
>>>>>
>>>>> If you can build your own kernel as Ilya says I'd like to
>>>>> see the values of which and img_request->next_completion
>>>>> here.
>>>>
>>>> Looks like which was 1, which means that next_completion had to be 2 or
>>>> greater.  I miss solaris crash dumps ...
>>>>
>>>> On a different note, why are we asserting next_completion outside of
>>>> a spinlock which is supposed to protect next_completion?
>>>
>>> That's a very good point (which could be easily remedied by moving
>>> the assertion down a couple lines).  The image object request (#1)
>>> in this case will have been marked done at this point; it's possible
>>> that request #2 (or later) was concurrently getting handled by the
>>> for_each_obj_request_from() loop below in that same function, but
>>> may not have updated next_completion yet.
>>>
>>> So that *could* explain the tripped assertion.  The assertion
>>> should be moved in any case, it's a bug.
>>>
>>> That being said, it doesn't explain the other assertion:
>>>         rbd_assert(img_request != NULL);
>>> So there's at least one other thing going on.
>>
>> Yeah, exactly my thoughts.
>>
>> Thanks,
>>
>>                 Ilya
> 
> So, a (partial) fix can be this patch ?
> 
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -2123,6 +2123,7 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
>         rbd_assert(obj_request_img_data_test(obj_request));
>         img_request = obj_request->img_request;
>  
> +       spin_lock_irq(&img_request->completion_lock);
>         dout("%s: img %p obj %p\n", __func__, img_request, obj_request);
>         rbd_assert(img_request != NULL);
>         rbd_assert(img_request->obj_request_count > 0);
> @@ -2130,7 +2131,6 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
>         rbd_assert(which < img_request->obj_request_count);
>         rbd_assert(which >= img_request->next_completion);
>  
> -       spin_lock_irq(&img_request->completion_lock);
>         if (which != img_request->next_completion)
>                 goto out;


Yes, roughly.  I'd do the following instead.  It would be great
to learn whether it eliminates the one form of assertion failure
you were seeing.

					-Alex

--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2128,11 +2128,11 @@ static void rbd_img_obj_callback(struct
 	rbd_assert(img_request->obj_request_count > 0);
 	rbd_assert(which != BAD_WHICH);
 	rbd_assert(which < img_request->obj_request_count);
-	rbd_assert(which >= img_request->next_completion);

 	spin_lock_irq(&img_request->completion_lock);
 	if (which != img_request->next_completion)
 		goto out;
+	rbd_assert(which > img_request->next_completion);

 	for_each_obj_request_from(img_request, obj_request) {
 		rbd_assert(more);


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

...
>> So, a (partial) fix can be this patch ?
>>
>> --- a/drivers/block/rbd.c
>> +++ b/drivers/block/rbd.c
>> @@ -2123,6 +2123,7 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
>>         rbd_assert(obj_request_img_data_test(obj_request));
>>         img_request = obj_request->img_request;
>>  
>> +       spin_lock_irq(&img_request->completion_lock);
>>         dout("%s: img %p obj %p\n", __func__, img_request, obj_request);
>>         rbd_assert(img_request != NULL);
>>         rbd_assert(img_request->obj_request_count > 0);
>> @@ -2130,7 +2131,6 @@ static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
>>         rbd_assert(which < img_request->obj_request_count);
>>         rbd_assert(which >= img_request->next_completion);
>>  
>> -       spin_lock_irq(&img_request->completion_lock);
>>         if (which != img_request->next_completion)
>>                 goto out;
> 
> 
> Yes, roughly.  I'd do the following instead.  It would be great
> to learn whether it eliminates the one form of assertion failure
> you were seeing.
> 
> 					-Alex
>


Strike that, my last patch was dead wrong.  Sorry.  Try this:

--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2128,11 +2128,11 @@ static void rbd_img_obj_callback(struct
 	rbd_assert(img_request->obj_request_count > 0);
 	rbd_assert(which != BAD_WHICH);
 	rbd_assert(which < img_request->obj_request_count);
-	rbd_assert(which >= img_request->next_completion);

 	spin_lock_irq(&img_request->completion_lock);
-	if (which != img_request->next_completion)
+	if (which > img_request->next_completion)
 		goto out;
+	rbd_assert(which == img_request->next_completion);

 	for_each_obj_request_from(img_request, obj_request) {
 		rbd_assert(more);

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 08:31 -0500, Alex Elder a écrit :
> ...
> >> So, a (partial) fix can be this patch ?
> >>
> > 
> > 
> > Yes, roughly.  I'd do the following instead.  It would be great
> > to learn whether it eliminates the one form of assertion failure
> > you were seeing.
> > 
> > 					-Alex
> >
> 
> 
> Strike that, my last patch was dead wrong.  Sorry.  Try this:
> 
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -2128,11 +2128,11 @@ static void rbd_img_obj_callback(struct
>  	rbd_assert(img_request->obj_request_count > 0);
>  	rbd_assert(which != BAD_WHICH);
>  	rbd_assert(which < img_request->obj_request_count);
> -	rbd_assert(which >= img_request->next_completion);
> 
>  	spin_lock_irq(&img_request->completion_lock);
> -	if (which != img_request->next_completion)
> +	if (which > img_request->next_completion)
>  		goto out;
> +	rbd_assert(which == img_request->next_completion);
> 
>  	for_each_obj_request_from(img_request, obj_request) {
>  		rbd_assert(more);
> 

Thanks !

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 08:31 -0500, Alex Elder a écrit :
> ...
> >> So, a (partial) fix can be this patch ?
> >>
> > 
> > 
> > Yes, roughly.  I'd do the following instead.  It would be great
> > to learn whether it eliminates the one form of assertion failure
> > you were seeing.
> > 
> > 					-Alex
> >
> 
> 
> Strike that, my last patch was dead wrong.  Sorry.  Try this:
> 
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -2128,11 +2128,11 @@ static void rbd_img_obj_callback(struct
>  	rbd_assert(img_request->obj_request_count > 0);
>  	rbd_assert(which != BAD_WHICH);
>  	rbd_assert(which < img_request->obj_request_count);
> -	rbd_assert(which >= img_request->next_completion);
> 
>  	spin_lock_irq(&img_request->completion_lock);
> -	if (which != img_request->next_completion)
> +	if (which > img_request->next_completion)
>  		goto out;
> +	rbd_assert(which == img_request->next_completion);
> 
>  	for_each_obj_request_from(img_request, obj_request) {
>  		rbd_assert(more);
> 
> 
> 

Well, it just hang :

Mar 25 17:58:36 rurkh kernel: [ 4135.913079] Assertion failure in rbd_img_obj_callback() at line 2135:
Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 
Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 	rbd_assert(which == img_request->next_completion);
Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 
Mar 25 17:58:36 rurkh kernel: [ 4135.913252] ------------[ cut here ]------------
Mar 25 17:58:36 rurkh kernel: [ 4135.913288] kernel BUG at drivers/block/rbd.c:2135!
Mar 25 17:58:36 rurkh kernel: [ 4135.913331] invalid opcode: 0000 [#1] SMP 
Mar 25 17:58:36 rurkh kernel: [ 4135.913373] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt iTCO_vendor_support gpio_ich serio_raw sb_edac edac_core i2c_i801 lpc_ich mfd_core evdev ioatdma shpchp ipmi_si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common isci ahci libsas libahci megaraid_sas libata scsi_transport_sas ehci_pci igb scsi_mod ehci_hcd ixgbe i2c_algo_bit i2c_core usbcore dca ptp usb_common pps_core mdio
Mar 25 17:58:36 rurkh kernel: [ 4135.913821] CPU: 0 PID: 30629 Comm: kworker/0:1 Not tainted 3.13-dae-dom0 #20
Mar 25 17:58:36 rurkh kernel: [ 4135.913863] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
Mar 25 17:58:36 rurkh kernel: [ 4135.913931] Workqueue: ceph-msgr con_work [libceph]
Mar 25 17:58:36 rurkh kernel: [ 4135.913970] task: ffff88027374b760 ti: ffff88024933c000 task.ti: ffff88024933c000
Mar 25 17:58:36 rurkh kernel: [ 4135.914033] RIP: e030:[<ffffffffa0304b86>]  [<ffffffffa0304b86>] rbd_img_obj_callback+0x12f/0x3d0 [rbd]
Mar 25 17:58:36 rurkh kernel: [ 4135.914104] RSP: e02b:ffff88024933dce8  EFLAGS: 00010082
Mar 25 17:58:36 rurkh kernel: [ 4135.914141] RAX: 0000000000000070 RBX: ffff88024d2dcc48 RCX: 0000000000000000
Mar 25 17:58:36 rurkh kernel: [ 4135.914182] RDX: ffff88027fe0eb50 RSI: ffff88027fe0e1a8 RDI: ffff8802493300a8
Mar 25 17:58:36 rurkh kernel: [ 4135.914223] RBP: ffff88024ccc3e20 R08: 0000000000000000 R09: 0000000000000000
Mar 25 17:58:36 rurkh kernel: [ 4135.914265] R10: 0000000000000000 R11: 0000000000000098 R12: 0000000000000001
Mar 25 17:58:36 rurkh kernel: [ 4135.914306] R13: 0000000000000000 R14: ffff88027144b1d0 R15: 0000000000000000
Mar 25 17:58:36 rurkh kernel: [ 4135.914351] FS:  00007f6ec996f700(0000) GS:ffff88027fe00000(0000) knlGS:0000000000000000
Mar 25 17:58:36 rurkh kernel: [ 4135.914415] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 25 17:58:36 rurkh kernel: [ 4135.914453] CR2: 0000000001ff1b10 CR3: 00000002492b3000 CR4: 0000000000042660
Mar 25 17:58:36 rurkh kernel: [ 4135.914495] Stack:
Mar 25 17:58:36 rurkh kernel: [ 4135.914524]  ffff88024ccc3e5c ffff88024a48eb5d ffffffffffffffff ffff88024a48eb28
Mar 25 17:58:36 rurkh kernel: [ 4135.914610]  ffff88027144b1c8 ffff8802656cc718 0000000000000000 ffff88027144b1d0
Mar 25 17:58:36 rurkh kernel: [ 4135.914689]  0000000000000000 ffffffffa02e3595 0000000000000015 ffff8802656cc770
Mar 25 17:58:36 rurkh kernel: [ 4135.914768] Call Trace:
Mar 25 17:58:36 rurkh kernel: [ 4135.914809]  [<ffffffffa02e3595>] ? dispatch+0x3e4/0x55e [libceph]
Mar 25 17:58:36 rurkh kernel: [ 4135.914854]  [<ffffffffa02de0fc>] ? con_work+0xf6e/0x1a65 [libceph]
Mar 25 17:58:36 rurkh kernel: [ 4135.914901]  [<ffffffff81005f00>] ? xen_timer_resume+0x4f/0x4f
Mar 25 17:58:36 rurkh kernel: [ 4135.914944]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
Mar 25 17:58:36 rurkh kernel: [ 4135.914984]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
Mar 25 17:58:36 rurkh kernel: [ 4135.915029]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
Mar 25 17:58:36 rurkh kernel: [ 4135.915072]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
Mar 25 17:58:36 rurkh kernel: [ 4135.915113]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
Mar 25 17:58:36 rurkh kernel: [ 4135.915155]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
Mar 25 17:58:36 rurkh kernel: [ 4135.915195]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Mar 25 17:58:36 rurkh kernel: [ 4135.915238]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
Mar 25 17:58:36 rurkh kernel: [ 4135.915279]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Mar 25 17:58:36 rurkh kernel: [ 4135.915319] Code: 41 b5 01 48 89 44 24 08 eb 3b 48 c7 c1 2e 7c 30 a0 ba 57 08 00 00 31 c0 48 c7 c6 80 89 30 a0 48 c7 c7 1f 71 30 a0 e8 bd 35 06 e1 <0f> 0b 41 8b 45 5c ff c8 39 43 40 41 0f 92 c5 48 8b 5b 30 41 ff 
Mar 25 17:58:36 rurkh kernel: [ 4135.915701] RIP  [<ffffffffa0304b86>] rbd_img_obj_callback+0x12f/0x3d0 [rbd]
Mar 25 17:58:36 rurkh kernel: [ 4135.915749]  RSP <ffff88024933dce8>
Mar 25 17:58:36 rurkh kernel: [ 4135.916087] ---[ end trace ff823e5e2d6cd4e9 ]--




--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 12:15 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 08:31 -0500, Alex Elder a écrit :
>> ...
>>>> So, a (partial) fix can be this patch ?
>>>>
>>>
>>>
>>> Yes, roughly.  I'd do the following instead.  It would be great
>>> to learn whether it eliminates the one form of assertion failure
>>> you were seeing.
>>>
>>> 					-Alex
>>>
>>
>>
>> Strike that, my last patch was dead wrong.  Sorry.  Try this:
>>
>> --- a/drivers/block/rbd.c
>> +++ b/drivers/block/rbd.c
>> @@ -2128,11 +2128,11 @@ static void rbd_img_obj_callback(struct
>>  	rbd_assert(img_request->obj_request_count > 0);
>>  	rbd_assert(which != BAD_WHICH);
>>  	rbd_assert(which < img_request->obj_request_count);
>> -	rbd_assert(which >= img_request->next_completion);
>>
>>  	spin_lock_irq(&img_request->completion_lock);
>> -	if (which != img_request->next_completion)
>> +	if (which > img_request->next_completion)
>>  		goto out;
>> +	rbd_assert(which == img_request->next_completion);
>>
>>  	for_each_obj_request_from(img_request, obj_request) {
>>  		rbd_assert(more);
>>
>>
>>
> 
> Well, it just hang :

It's great to know you can reproduce this.

Let me put together another quick patch that might supply a bit
more information when it happens.  I'll send something shortly.

					-Alex

> Mar 25 17:58:36 rurkh kernel: [ 4135.913079] Assertion failure in rbd_img_obj_callback() at line 2135:
> Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 
> Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 	rbd_assert(which == img_request->next_completion);
> Mar 25 17:58:36 rurkh kernel: [ 4135.913079] 
> Mar 25 17:58:36 rurkh kernel: [ 4135.913252] ------------[ cut here ]------------
> Mar 25 17:58:36 rurkh kernel: [ 4135.913288] kernel BUG at drivers/block/rbd.c:2135!
> Mar 25 17:58:36 rurkh kernel: [ 4135.913331] invalid opcode: 0000 [#1] SMP 
> Mar 25 17:58:36 rurkh kernel: [ 4135.913373] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt iTCO_vendor_support gpio_ich serio_raw sb_edac edac_core i2c_i801 lpc_ich mfd_core evdev ioatdma shpchp ipmi_si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common isci ahci libsas libahci megaraid_sas libata scsi_transport_sas ehci_pci igb scsi_mod ehci_hcd ixgbe i2c_algo_bit i2c_core usbcore dca ptp usb_common pps_core mdio
> Mar 25 17:58:36 rurkh kernel: [ 4135.913821] CPU: 0 PID: 30629 Comm: kworker/0:1 Not tainted 3.13-dae-dom0 #20
> Mar 25 17:58:36 rurkh kernel: [ 4135.913863] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
> Mar 25 17:58:36 rurkh kernel: [ 4135.913931] Workqueue: ceph-msgr con_work [libceph]
> Mar 25 17:58:36 rurkh kernel: [ 4135.913970] task: ffff88027374b760 ti: ffff88024933c000 task.ti: ffff88024933c000
> Mar 25 17:58:36 rurkh kernel: [ 4135.914033] RIP: e030:[<ffffffffa0304b86>]  [<ffffffffa0304b86>] rbd_img_obj_callback+0x12f/0x3d0 [rbd]
> Mar 25 17:58:36 rurkh kernel: [ 4135.914104] RSP: e02b:ffff88024933dce8  EFLAGS: 00010082
> Mar 25 17:58:36 rurkh kernel: [ 4135.914141] RAX: 0000000000000070 RBX: ffff88024d2dcc48 RCX: 0000000000000000
> Mar 25 17:58:36 rurkh kernel: [ 4135.914182] RDX: ffff88027fe0eb50 RSI: ffff88027fe0e1a8 RDI: ffff8802493300a8
> Mar 25 17:58:36 rurkh kernel: [ 4135.914223] RBP: ffff88024ccc3e20 R08: 0000000000000000 R09: 0000000000000000
> Mar 25 17:58:36 rurkh kernel: [ 4135.914265] R10: 0000000000000000 R11: 0000000000000098 R12: 0000000000000001
> Mar 25 17:58:36 rurkh kernel: [ 4135.914306] R13: 0000000000000000 R14: ffff88027144b1d0 R15: 0000000000000000
> Mar 25 17:58:36 rurkh kernel: [ 4135.914351] FS:  00007f6ec996f700(0000) GS:ffff88027fe00000(0000) knlGS:0000000000000000
> Mar 25 17:58:36 rurkh kernel: [ 4135.914415] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
> Mar 25 17:58:36 rurkh kernel: [ 4135.914453] CR2: 0000000001ff1b10 CR3: 00000002492b3000 CR4: 0000000000042660
> Mar 25 17:58:36 rurkh kernel: [ 4135.914495] Stack:
> Mar 25 17:58:36 rurkh kernel: [ 4135.914524]  ffff88024ccc3e5c ffff88024a48eb5d ffffffffffffffff ffff88024a48eb28
> Mar 25 17:58:36 rurkh kernel: [ 4135.914610]  ffff88027144b1c8 ffff8802656cc718 0000000000000000 ffff88027144b1d0
> Mar 25 17:58:36 rurkh kernel: [ 4135.914689]  0000000000000000 ffffffffa02e3595 0000000000000015 ffff8802656cc770
> Mar 25 17:58:36 rurkh kernel: [ 4135.914768] Call Trace:
> Mar 25 17:58:36 rurkh kernel: [ 4135.914809]  [<ffffffffa02e3595>] ? dispatch+0x3e4/0x55e [libceph]
> Mar 25 17:58:36 rurkh kernel: [ 4135.914854]  [<ffffffffa02de0fc>] ? con_work+0xf6e/0x1a65 [libceph]
> Mar 25 17:58:36 rurkh kernel: [ 4135.914901]  [<ffffffff81005f00>] ? xen_timer_resume+0x4f/0x4f
> Mar 25 17:58:36 rurkh kernel: [ 4135.914944]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
> Mar 25 17:58:36 rurkh kernel: [ 4135.914984]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
> Mar 25 17:58:36 rurkh kernel: [ 4135.915029]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
> Mar 25 17:58:36 rurkh kernel: [ 4135.915072]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
> Mar 25 17:58:36 rurkh kernel: [ 4135.915113]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
> Mar 25 17:58:36 rurkh kernel: [ 4135.915155]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
> Mar 25 17:58:36 rurkh kernel: [ 4135.915195]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Mar 25 17:58:36 rurkh kernel: [ 4135.915238]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
> Mar 25 17:58:36 rurkh kernel: [ 4135.915279]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Mar 25 17:58:36 rurkh kernel: [ 4135.915319] Code: 41 b5 01 48 89 44 24 08 eb 3b 48 c7 c1 2e 7c 30 a0 ba 57 08 00 00 31 c0 48 c7 c6 80 89 30 a0 48 c7 c7 1f 71 30 a0 e8 bd 35 06 e1 <0f> 0b 41 8b 45 5c ff c8 39 43 40 41 0f 92 c5 48 8b 5b 30 41 ff 
> Mar 25 17:58:36 rurkh kernel: [ 4135.915701] RIP  [<ffffffffa0304b86>] rbd_img_obj_callback+0x12f/0x3d0 [rbd]
> Mar 25 17:58:36 rurkh kernel: [ 4135.915749]  RSP <ffff88024933dce8>
> Mar 25 17:58:36 rurkh kernel: [ 4135.916087] ---[ end trace ff823e5e2d6cd4e9 ]--
> 
> 
> 
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 12:21 -0500, Alex Elder a écrit :
> It's great to know you can reproduce this.

Yes... I understand your point of view but... it's a production
cluster ;)

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

Please try applying this, on top of the previous patch.
If you can then reproduce the problem we'll have a bunch
of new information about the particular request that's
leading to the failure.  That might tell us what more we
can do to find the root cause.  Thank you.

					-Alex

PS  I hope my mailer doesn't botch the long lines.  It might.

---
 drivers/block/rbd.c |   25 ++++++++++++++++++++++++-
 1 file changed, 24 insertions(+), 1 deletion(-)

Index: b/drivers/block/rbd.c
===================================================================
--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2132,7 +2132,30 @@ static void rbd_img_obj_callback(struct
 	spin_lock_irq(&img_request->completion_lock);
 	if (which > img_request->next_completion)
 		goto out;
-	rbd_assert(which == img_request->next_completion);
+	if (which != img_request->next_completion) {
+		printk("%s: bad image object request information:\n", __func__);
+		printk("obj_request %p\n", obj_request);
+		printk("    ->object_name <%s>\n", obj_request->object_name);
+		printk("    ->offset %llu\n", obj_request->offset);
+		printk("    ->length %llu\n", obj_request->length);
+		printk("    ->type 0x%x\n", (u32)obj_request->type);
+		printk("    ->flags 0x%lx\n", obj_request->flags);
+		printk("    ->which %u\n", obj_request->which);
+		printk("    ->xferred %llu\n", obj_request->xferred);
+		printk("    ->result %d\n", obj_request->result);
+
+		printk("img_request %p\n", img_request);
+		printk("    ->snap 0x%016llx\n", img_request->snap_id);
+		printk("    ->offset %llu\n", img_request->offset);
+		printk("    ->length %llu\n", img_request->length);
+		printk("    ->flags 0x%lx\n", img_request->flags);
+		printk("    ->obj_request_count %u\n",
+			img_request->obj_request_count);
+		printk("    ->next_completion %u\n",
+			img_request->next_completion);
+		printk("    ->xferred %llu\n", img_request->xferred);
+		printk("    ->result %d\n", img_request->result);
+	}

 	for_each_obj_request_from(img_request, obj_request) {
 		rbd_assert(more);

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
> Please try applying this, on top of the previous patch.
> If you can then reproduce the problem we'll have a bunch
> of new information about the particular request that's
> leading to the failure.  That might tell us what more we
> can do to find the root cause.  Thank you.
> 
> 					-Alex
> 
> PS  I hope my mailer doesn't botch the long lines.  It might.
> 

Here the execution will continue, no more kernel panic after this
debugging display. Is it wanted ?

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
>> Please try applying this, on top of the previous patch.
>> If you can then reproduce the problem we'll have a bunch
>> of new information about the particular request that's
>> leading to the failure.  That might tell us what more we
>> can do to find the root cause.  Thank you.
>>
>> 					-Alex
>>
>> PS  I hope my mailer doesn't botch the long lines.  It might.
>>
> 
> Here the execution will continue, no more kernel panic after this
> debugging display. Is it wanted ?


I guess it should panic.  I'm glad you mentioned this.

I'm sorry to have it reproducing on a production cluster.
Unfortunately at this point it's the only place we've
been able to reproduce it (and with any luck we'll find
the problem soon).

					-Alex
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
> On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
>> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
>>> Please try applying this, on top of the previous patch.
>>> If you can then reproduce the problem we'll have a bunch
>>> of new information about the particular request that's
>>> leading to the failure.  That might tell us what more we
>>> can do to find the root cause.  Thank you.
>>>
>>>                                      -Alex
>>>
>>> PS  I hope my mailer doesn't botch the long lines.  It might.
>>>
>>
>> Here the execution will continue, no more kernel panic after this
>> debugging display. Is it wanted ?
>
>
> I guess it should panic.  I'm glad you mentioned this.

Just in case, if you haven't done it already: stick rbd_assert(0);
after the last printk in that if statement, so it looks like this:

if (which != img_request->next_completion) {
        printk("%s: bad image object request information:\n", __func__);
        printk("obj_request %p\n", obj_request);
        printk("    ->object_name <%s>\n", obj_request->object_name);
        ...

        printk("img_request %p\n", img_request);
        printk("    ->snap 0x%016llx\n", img_request->snap_id);
        ...
        printk("    ->result %d\n", img_request->result);

        rbd_assert(0);
}

Thanks,

                Ilya
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 22:18 +0200, Ilya Dryomov a écrit :
> On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
> > On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
> >> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
> >>> Please try applying this, on top of the previous patch.
> >>> If you can then reproduce the problem we'll have a bunch
> >>> of new information about the particular request that's
> >>> leading to the failure.  That might tell us what more we
> >>> can do to find the root cause.  Thank you.
> >>>
> >>>                                      -Alex
> >>>
> >>> PS  I hope my mailer doesn't botch the long lines.  It might.
> >>>
> >>
> >> Here the execution will continue, no more kernel panic after this
> >> debugging display. Is it wanted ?
> >
> >
> > I guess it should panic.  I'm glad you mentioned this.
> 
> Just in case, if you haven't done it already: stick rbd_assert(0);
> after the last printk in that if statement, so it looks like this:
> 
> if (which != img_request->next_completion) {
>         printk("%s: bad image object request information:\n", __func__);
>         printk("obj_request %p\n", obj_request);
>         printk("    ->object_name <%s>\n", obj_request->object_name);
>         ...
> 
>         printk("img_request %p\n", img_request);
>         printk("    ->snap 0x%016llx\n", img_request->snap_id);
>         ...
>         printk("    ->result %d\n", img_request->result);
> 
>         rbd_assert(0);
> }
> 
> Thanks,
> 
>                 Ilya
> 

Without the rbd_assert(0), I add this hang :


Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1
Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0
Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
Mar 25 21:17:58 murmillia kernel: [ 2205.255962] Assertion failure in rbd_img_obj_callback() at line 2162:
Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 	rbd_assert(which < img_request->obj_request_count);
Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
Mar 25 21:17:58 murmillia kernel: [ 2205.256141] ------------[ cut here ]------------
Mar 25 21:17:58 murmillia kernel: [ 2205.256178] kernel BUG at drivers/block/rbd.c:2162!


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 03:21 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 22:18 +0200, Ilya Dryomov a écrit :
>> On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
>>> On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
>>>> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
>>>>> Please try applying this, on top of the previous patch.
>>>>> If you can then reproduce the problem we'll have a bunch
>>>>> of new information about the particular request that's
>>>>> leading to the failure.  That might tell us what more we
>>>>> can do to find the root cause.  Thank you.
>>>>>
>>>>>                                      -Alex
>>>>>
>>>>> PS  I hope my mailer doesn't botch the long lines.  It might.
>>>>>
>>>>
>>>> Here the execution will continue, no more kernel panic after this
>>>> debugging display. Is it wanted ?
>>>
>>>
>>> I guess it should panic.  I'm glad you mentioned this.
>>
>> Just in case, if you haven't done it already: stick rbd_assert(0);
>> after the last printk in that if statement, so it looks like this:
>>
>> if (which != img_request->next_completion) {
>>         printk("%s: bad image object request information:\n", __func__);
>>         printk("obj_request %p\n", obj_request);
>>         printk("    ->object_name <%s>\n", obj_request->object_name);
>>         ...
>>
>>         printk("img_request %p\n", img_request);
>>         printk("    ->snap 0x%016llx\n", img_request->snap_id);
>>         ...
>>         printk("    ->result %d\n", img_request->result);
>>
>>         rbd_assert(0);
>> }
>>
>> Thanks,
>>
>>                 Ilya
>>
> 
> Without the rbd_assert(0), I add this hang :
> 
> 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
> Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
> Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
		BIO request

> Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
	IMG_DATA, KNOWN

> Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
	Second object in the request

> Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
> Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
> Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
	!!! There is only one request... (?)

So obj_request_count might be getting computed incorrectly.

					-Alex

> Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
> Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] Assertion failure in rbd_img_obj_callback() at line 2162:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 	rbd_assert(which < img_request->obj_request_count);
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.256141] ------------[ cut here ]------------
> Mar 25 21:17:58 murmillia kernel: [ 2205.256178] kernel BUG at drivers/block/rbd.c:2162!
> 
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 15:24 -0500, Alex Elder a écrit :
> On 03/25/2014 03:21 PM, Olivier Bonvalet wrote:
> > Le mardi 25 mars 2014 à 22:18 +0200, Ilya Dryomov a écrit :
> >> On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
> >>> On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
> >>>> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
> >>>>> Please try applying this, on top of the previous patch.
> >>>>> If you can then reproduce the problem we'll have a bunch
> >>>>> of new information about the particular request that's
> >>>>> leading to the failure.  That might tell us what more we
> >>>>> can do to find the root cause.  Thank you.
> >>>>>
> >>>>>                                      -Alex
> >>>>>
> >>>>> PS  I hope my mailer doesn't botch the long lines.  It might.
> >>>>>
> >>>>
> >>>> Here the execution will continue, no more kernel panic after this
> >>>> debugging display. Is it wanted ?
> >>>
> >>>
> >>> I guess it should panic.  I'm glad you mentioned this.
> >>
> >> Just in case, if you haven't done it already: stick rbd_assert(0);
> >> after the last printk in that if statement, so it looks like this:
> >>
> >> if (which != img_request->next_completion) {
> >>         printk("%s: bad image object request information:\n", __func__);
> >>         printk("obj_request %p\n", obj_request);
> >>         printk("    ->object_name <%s>\n", obj_request->object_name);
> >>         ...
> >>
> >>         printk("img_request %p\n", img_request);
> >>         printk("    ->snap 0x%016llx\n", img_request->snap_id);
> >>         ...
> >>         printk("    ->result %d\n", img_request->result);
> >>
> >>         rbd_assert(0);
> >> }
> >>
> >> Thanks,
> >>
> >>                 Ilya
> >>
> > 
> > Without the rbd_assert(0), I add this hang :
> > 
> > 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
> 		BIO request
> 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
> 	IMG_DATA, KNOWN
> 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
> 	Second object in the request
> 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
> 	!!! There is only one request... (?)
> 
> So obj_request_count might be getting computed incorrectly.
> 
> 					-Alex
> 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] Assertion failure in rbd_img_obj_callback() at line 2162:
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 	rbd_assert(which < img_request->obj_request_count);
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.256141] ------------[ cut here ]------------
> > Mar 25 21:17:58 murmillia kernel: [ 2205.256178] kernel BUG at drivers/block/rbd.c:2162!
> > 
> > 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 


Here I was migrating (xen live migrate) ~20 VM from one host to
"murmillia", just after booting "murmillia" on the new kernel.

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

Olivier, it appears this is a layered image, i.e., the image
is a clone of another.  Can you tell us any more about the
way these images are organized?  Do you have one master image
and others are based on that?  Is there more than one layer to
the organization?  (Do these questions make sense?)

					-Alex

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

[Olivier Bonvalet]

For me all this images are RBD v1 images, without layering.

# rbd info sas3copies/env4-spool
rbd image 'env4-spool':
	size 10240 MB in 2560 objects
	order 22 (4096 KB objects)
	block_name_prefix: rb.0.1536881.238e1f29
	format: 1

(the one reported here : 
Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
)

At VM level, this block device is formated in ext4, and used for Exim4
(MTA) spool, and can handle a lots of writes.

And this ceph pool use 3 replica, with a "per network" CRUSH rule.


Le mardi 25 mars 2014 à 15:44 -0500, Alex Elder a écrit :
> Olivier, it appears this is a layered image, i.e., the image
> is a clone of another.  Can you tell us any more about the
> way these images are organized?  Do you have one master image
> and others are based on that?  Is there more than one layer to
> the organization?  (Do these questions make sense?)
> 
> 					-Alex
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 03:21 PM, Olivier Bonvalet wrote:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
> Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
> Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
> Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
> Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
> Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1

The image request has IMG_REQ_CHILD set.  That means it's a request
sent to a parent image.

I see one thing that I'm suspicious of, but I'll need to look at it
a bit to see if it's really a problem.

In rbd_parent_request_destroy(), should this last line:
        rbd_img_request_destroy(kref);
be this instead?
	rbd_img_request_put(parent_request);

And get rid of this line above that:
        img_request_child_clear(parent_request);

Something to look at.  Also the fact that it's a parent
request with two objects involved seems strange, but
again, I'm just speculating at this point.

					-Alex

> Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
> Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 21:21 +0100, Olivier Bonvalet a écrit :
> Le mardi 25 mars 2014 à 22:18 +0200, Ilya Dryomov a écrit :
> > On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
> > > On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
> > >> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
> > >>> Please try applying this, on top of the previous patch.
> > >>> If you can then reproduce the problem we'll have a bunch
> > >>> of new information about the particular request that's
> > >>> leading to the failure.  That might tell us what more we
> > >>> can do to find the root cause.  Thank you.
> > >>>
> > >>>                                      -Alex
> > >>>
> > >>> PS  I hope my mailer doesn't botch the long lines.  It might.
> > >>>
> > >>
> > >> Here the execution will continue, no more kernel panic after this
> > >> debugging display. Is it wanted ?
> > >
> > >
> > > I guess it should panic.  I'm glad you mentioned this.
> > 
> > Just in case, if you haven't done it already: stick rbd_assert(0);
> > after the last printk in that if statement, so it looks like this:
> > 
> > if (which != img_request->next_completion) {
> >         printk("%s: bad image object request information:\n", __func__);
> >         printk("obj_request %p\n", obj_request);
> >         printk("    ->object_name <%s>\n", obj_request->object_name);
> >         ...
> > 
> >         printk("img_request %p\n", img_request);
> >         printk("    ->snap 0x%016llx\n", img_request->snap_id);
> >         ...
> >         printk("    ->result %d\n", img_request->result);
> > 
> >         rbd_assert(0);
> > }
> > 
> > Thanks,
> > 
> >                 Ilya
> > 
> 
> Without the rbd_assert(0), I add this hang :
> 
> 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
> Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
> Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
> Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
> Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
> Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
> Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
> Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
> Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
> Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] Assertion failure in rbd_img_obj_callback() at line 2162:
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 	rbd_assert(which < img_request->obj_request_count);
> Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> Mar 25 21:17:58 murmillia kernel: [ 2205.256141] ------------[ cut here ]------------
> Mar 25 21:17:58 murmillia kernel: [ 2205.256178] kernel BUG at drivers/block/rbd.c:2162!
> 
> 
> --

An other one :

Mar 25 21:52:50 alg kernel: [ 1781.377690] rbd_img_obj_callback: bad image object request information:
Mar 25 21:52:50 alg kernel: [ 1781.377696] obj_request ffff88021dda2ae8
Mar 25 21:52:50 alg kernel: [ 1781.377698]     ->object_name <(null)>
Mar 25 21:52:50 alg kernel: [ 1781.377699]     ->offset 0
Mar 25 21:52:50 alg kernel: [ 1781.377701]     ->length 12288
Mar 25 21:52:50 alg kernel: [ 1781.377702]     ->type 0x1
Mar 25 21:52:50 alg kernel: [ 1781.377703]     ->flags 0x3
Mar 25 21:52:50 alg kernel: [ 1781.377704]     ->which 4294967295
Mar 25 21:52:50 alg kernel: [ 1781.377705]     ->xferred 12288
Mar 25 21:52:50 alg kernel: [ 1781.377706]     ->result 0
Mar 25 21:52:50 alg kernel: [ 1781.377707] img_request ffff880223f396a0
Mar 25 21:52:50 alg kernel: [ 1781.377709]     ->snap 0xffff880231dd8cc0
Mar 25 21:52:50 alg kernel: [ 1781.377710]     ->offset 1119846400
Mar 25 21:52:50 alg kernel: [ 1781.377711]     ->length 45056
Mar 25 21:52:50 alg kernel: [ 1781.377712]     ->flags 0x1
Mar 25 21:52:50 alg kernel: [ 1781.377713]     ->obj_request_count 0
Mar 25 21:52:50 alg kernel: [ 1781.377713]     ->next_completion 2
Mar 25 21:52:50 alg kernel: [ 1781.377714]     ->xferred 45056
Mar 25 21:52:50 alg kernel: [ 1781.377715]     ->result 0
Mar 25 21:52:50 alg kernel: [ 1781.377717] 
Mar 25 21:52:50 alg kernel: [ 1781.377717] Assertion failure in rbd_img_obj_callback() at line 2162:
Mar 25 21:52:50 alg kernel: [ 1781.377717] 
Mar 25 21:52:50 alg kernel: [ 1781.377717] 	rbd_assert(which < img_request->obj_request_count);
Mar 25 21:52:50 alg kernel: [ 1781.377717] 
Mar 25 21:52:50 alg kernel: [ 1781.377859] ------------[ cut here ]------------


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 21:53 +0100, Olivier Bonvalet a écrit :
> Le mardi 25 mars 2014 à 21:21 +0100, Olivier Bonvalet a écrit :
> > Le mardi 25 mars 2014 à 22:18 +0200, Ilya Dryomov a écrit :
> > > On Tue, Mar 25, 2014 at 9:03 PM, Alex Elder <elder@ieee.org> wrote:
> > > > On 03/25/2014 01:53 PM, Olivier Bonvalet wrote:
> > > >> Le mardi 25 mars 2014 à 12:43 -0500, Alex Elder a écrit :
> > > >>> Please try applying this, on top of the previous patch.
> > > >>> If you can then reproduce the problem we'll have a bunch
> > > >>> of new information about the particular request that's
> > > >>> leading to the failure.  That might tell us what more we
> > > >>> can do to find the root cause.  Thank you.
> > > >>>
> > > >>>                                      -Alex
> > > >>>
> > > >>> PS  I hope my mailer doesn't botch the long lines.  It might.
> > > >>>
> > > >>
> > > >> Here the execution will continue, no more kernel panic after this
> > > >> debugging display. Is it wanted ?
> > > >
> > > >
> > > > I guess it should panic.  I'm glad you mentioned this.
> > > 
> > > Just in case, if you haven't done it already: stick rbd_assert(0);
> > > after the last printk in that if statement, so it looks like this:
> > > 
> > > if (which != img_request->next_completion) {
> > >         printk("%s: bad image object request information:\n", __func__);
> > >         printk("obj_request %p\n", obj_request);
> > >         printk("    ->object_name <%s>\n", obj_request->object_name);
> > >         ...
> > > 
> > >         printk("img_request %p\n", img_request);
> > >         printk("    ->snap 0x%016llx\n", img_request->snap_id);
> > >         ...
> > >         printk("    ->result %d\n", img_request->result);
> > > 
> > >         rbd_assert(0);
> > > }
> > > 
> > > Thanks,
> > > 
> > >                 Ilya
> > > 
> > 
> > Without the rbd_assert(0), I add this hang :
> > 
> > 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255933] rbd_img_obj_callback: bad image object request information:
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255938] obj_request ffff88025a2b3c48
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255940]     ->object_name <rb.0.1536881.238e1f29.000000000439>
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255941]     ->offset 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255943]     ->length 28672
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255944]     ->type 0x1
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255945]     ->flags 0x3
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255946]     ->which 1
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255948]     ->xferred 28672
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255949]     ->result 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255950] img_request ffff8802536c4a60
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255952]     ->snap 0xffff880257f85ec0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255953]     ->offset 4534026240
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255954]     ->length 45056
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255955]     ->flags 0x1
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255957]     ->obj_request_count 1
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255958]     ->next_completion 2
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255959]     ->xferred 45056
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255960]     ->result 0
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] Assertion failure in rbd_img_obj_callback() at line 2162:
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 	rbd_assert(which < img_request->obj_request_count);
> > Mar 25 21:17:58 murmillia kernel: [ 2205.255962] 
> > Mar 25 21:17:58 murmillia kernel: [ 2205.256141] ------------[ cut here ]------------
> > Mar 25 21:17:58 murmillia kernel: [ 2205.256178] kernel BUG at drivers/block/rbd.c:2162!
> > 
> > 
> > --
> 
> An other one :
> 
> Mar 25 21:52:50 alg kernel: [ 1781.377690] rbd_img_obj_callback: bad image object request information:
> Mar 25 21:52:50 alg kernel: [ 1781.377696] obj_request ffff88021dda2ae8
> Mar 25 21:52:50 alg kernel: [ 1781.377698]     ->object_name <(null)>
> Mar 25 21:52:50 alg kernel: [ 1781.377699]     ->offset 0
> Mar 25 21:52:50 alg kernel: [ 1781.377701]     ->length 12288
> Mar 25 21:52:50 alg kernel: [ 1781.377702]     ->type 0x1
> Mar 25 21:52:50 alg kernel: [ 1781.377703]     ->flags 0x3
> Mar 25 21:52:50 alg kernel: [ 1781.377704]     ->which 4294967295
> Mar 25 21:52:50 alg kernel: [ 1781.377705]     ->xferred 12288
> Mar 25 21:52:50 alg kernel: [ 1781.377706]     ->result 0
> Mar 25 21:52:50 alg kernel: [ 1781.377707] img_request ffff880223f396a0
> Mar 25 21:52:50 alg kernel: [ 1781.377709]     ->snap 0xffff880231dd8cc0
> Mar 25 21:52:50 alg kernel: [ 1781.377710]     ->offset 1119846400
> Mar 25 21:52:50 alg kernel: [ 1781.377711]     ->length 45056
> Mar 25 21:52:50 alg kernel: [ 1781.377712]     ->flags 0x1
> Mar 25 21:52:50 alg kernel: [ 1781.377713]     ->obj_request_count 0
> Mar 25 21:52:50 alg kernel: [ 1781.377713]     ->next_completion 2
> Mar 25 21:52:50 alg kernel: [ 1781.377714]     ->xferred 45056
> Mar 25 21:52:50 alg kernel: [ 1781.377715]     ->result 0
> Mar 25 21:52:50 alg kernel: [ 1781.377717] 
> Mar 25 21:52:50 alg kernel: [ 1781.377717] Assertion failure in rbd_img_obj_callback() at line 2162:
> Mar 25 21:52:50 alg kernel: [ 1781.377717] 
> Mar 25 21:52:50 alg kernel: [ 1781.377717] 	rbd_assert(which < img_request->obj_request_count);
> Mar 25 21:52:50 alg kernel: [ 1781.377717] 
> Mar 25 21:52:50 alg kernel: [ 1781.377859] ------------[ cut here ]------------
> 
> 
> --

The third (now with rbd_assort(0)) :

Mar 25 22:08:12 alg kernel: [  598.301895] rbd_img_obj_callback: bad image object request information:
Mar 25 22:08:12 alg kernel: [  598.301900] obj_request ffff88022409e1b8
Mar 25 22:08:12 alg kernel: [  598.301901]     ->object_name <(null)>
Mar 25 22:08:12 alg kernel: [  598.301902]     ->offset 0
Mar 25 22:08:12 alg kernel: [  598.301903]     ->length 8192
Mar 25 22:08:12 alg kernel: [  598.301904]     ->type 0x1
Mar 25 22:08:12 alg kernel: [  598.301905]     ->flags 0x3
Mar 25 22:08:12 alg kernel: [  598.301906]     ->which 4294967295
Mar 25 22:08:12 alg kernel: [  598.301906]     ->xferred 8192
Mar 25 22:08:12 alg kernel: [  598.301907]     ->result 0
Mar 25 22:08:12 alg kernel: [  598.301908] img_request ffff8802303bff10
Mar 25 22:08:12 alg kernel: [  598.301909]     ->snap 0xffff88022711f500
Mar 25 22:08:12 alg kernel: [  598.301910]     ->offset 4492079104
Mar 25 22:08:12 alg kernel: [  598.301911]     ->length 28672
Mar 25 22:08:12 alg kernel: [  598.301912]     ->flags 0x1
Mar 25 22:08:12 alg kernel: [  598.301913]     ->obj_request_count 0
Mar 25 22:08:12 alg kernel: [  598.301913]     ->next_completion 2
Mar 25 22:08:12 alg kernel: [  598.301914]     ->xferred 28672
Mar 25 22:08:12 alg kernel: [  598.301915]     ->result 0
Mar 25 22:08:12 alg kernel: [  598.301916] 
Mar 25 22:08:12 alg kernel: [  598.301916] Assertion failure in rbd_img_obj_callback() at line 2159:
Mar 25 22:08:12 alg kernel: [  598.301916] 
Mar 25 22:08:12 alg kernel: [  598.301916] 	rbd_assert(0);
Mar 25 22:08:12 alg kernel: [  598.301916] 
Mar 25 22:08:12 alg kernel: [  598.302093] ------------[ cut here ]------------




--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 11:10 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> The third (now with rbd_assort(0)) :
>
> Mar 25 22:08:12 alg kernel: [  598.301895] rbd_img_obj_callback: bad image object request information:
> Mar 25 22:08:12 alg kernel: [  598.301900] obj_request ffff88022409e1b8
> Mar 25 22:08:12 alg kernel: [  598.301901]     ->object_name <(null)>
> Mar 25 22:08:12 alg kernel: [  598.301902]     ->offset 0
> Mar 25 22:08:12 alg kernel: [  598.301903]     ->length 8192
> Mar 25 22:08:12 alg kernel: [  598.301904]     ->type 0x1
> Mar 25 22:08:12 alg kernel: [  598.301905]     ->flags 0x3
> Mar 25 22:08:12 alg kernel: [  598.301906]     ->which 4294967295
> Mar 25 22:08:12 alg kernel: [  598.301906]     ->xferred 8192
> Mar 25 22:08:12 alg kernel: [  598.301907]     ->result 0
> Mar 25 22:08:12 alg kernel: [  598.301908] img_request ffff8802303bff10
> Mar 25 22:08:12 alg kernel: [  598.301909]     ->snap 0xffff88022711f500
> Mar 25 22:08:12 alg kernel: [  598.301910]     ->offset 4492079104
> Mar 25 22:08:12 alg kernel: [  598.301911]     ->length 28672
> Mar 25 22:08:12 alg kernel: [  598.301912]     ->flags 0x1
> Mar 25 22:08:12 alg kernel: [  598.301913]     ->obj_request_count 0
> Mar 25 22:08:12 alg kernel: [  598.301913]     ->next_completion 2
> Mar 25 22:08:12 alg kernel: [  598.301914]     ->xferred 28672
> Mar 25 22:08:12 alg kernel: [  598.301915]     ->result 0
> Mar 25 22:08:12 alg kernel: [  598.301916]
> Mar 25 22:08:12 alg kernel: [  598.301916] Assertion failure in rbd_img_obj_callback() at line 2159:
> Mar 25 22:08:12 alg kernel: [  598.301916]
> Mar 25 22:08:12 alg kernel: [  598.301916]      rbd_assert(0);
> Mar 25 22:08:12 alg kernel: [  598.301916]
> Mar 25 22:08:12 alg kernel: [  598.302093] ------------[ cut here ]------------

Hmm...  Can you attach your drivers/block/rbd.c as of this third
occurence?

Thanks,

                Ilya

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 11:22 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> Le mardi 25 mars 2014 à 23:20 +0200, Ilya Dryomov a écrit :
>> On Tue, Mar 25, 2014 at 11:10 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>> > The third (now with rbd_assort(0)) :
>> >
>> > Mar 25 22:08:12 alg kernel: [  598.301895] rbd_img_obj_callback: bad image object request information:
>> > Mar 25 22:08:12 alg kernel: [  598.301900] obj_request ffff88022409e1b8
>> > Mar 25 22:08:12 alg kernel: [  598.301901]     ->object_name <(null)>
>> > Mar 25 22:08:12 alg kernel: [  598.301902]     ->offset 0
>> > Mar 25 22:08:12 alg kernel: [  598.301903]     ->length 8192
>> > Mar 25 22:08:12 alg kernel: [  598.301904]     ->type 0x1
>> > Mar 25 22:08:12 alg kernel: [  598.301905]     ->flags 0x3
>> > Mar 25 22:08:12 alg kernel: [  598.301906]     ->which 4294967295
>> > Mar 25 22:08:12 alg kernel: [  598.301906]     ->xferred 8192
>> > Mar 25 22:08:12 alg kernel: [  598.301907]     ->result 0
>> > Mar 25 22:08:12 alg kernel: [  598.301908] img_request ffff8802303bff10
>> > Mar 25 22:08:12 alg kernel: [  598.301909]     ->snap 0xffff88022711f500
>> > Mar 25 22:08:12 alg kernel: [  598.301910]     ->offset 4492079104
>> > Mar 25 22:08:12 alg kernel: [  598.301911]     ->length 28672
>> > Mar 25 22:08:12 alg kernel: [  598.301912]     ->flags 0x1
>> > Mar 25 22:08:12 alg kernel: [  598.301913]     ->obj_request_count 0
>> > Mar 25 22:08:12 alg kernel: [  598.301913]     ->next_completion 2
>> > Mar 25 22:08:12 alg kernel: [  598.301914]     ->xferred 28672
>> > Mar 25 22:08:12 alg kernel: [  598.301915]     ->result 0
>> > Mar 25 22:08:12 alg kernel: [  598.301916]
>> > Mar 25 22:08:12 alg kernel: [  598.301916] Assertion failure in rbd_img_obj_callback() at line 2159:
>> > Mar 25 22:08:12 alg kernel: [  598.301916]
>> > Mar 25 22:08:12 alg kernel: [  598.301916]      rbd_assert(0);
>> > Mar 25 22:08:12 alg kernel: [  598.301916]
>> > Mar 25 22:08:12 alg kernel: [  598.302093] ------------[ cut here ]------------
>>
>> Hmm...  Can you attach your drivers/block/rbd.c as of this third
>> occurence?
>>
>> Thanks,
>>
>>                 Ilya
>>
>
> Of course.

Sorry, I asked for the drivers/block/rbd.c C source file.

Thanks,

                Ilya
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 23:25 +0200, Ilya Dryomov a écrit :
> On Tue, Mar 25, 2014 at 11:22 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> > Le mardi 25 mars 2014 à 23:20 +0200, Ilya Dryomov a écrit :
> >> On Tue, Mar 25, 2014 at 11:10 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> >> > The third (now with rbd_assort(0)) :
> >> >
> >> > Mar 25 22:08:12 alg kernel: [  598.301895] rbd_img_obj_callback: bad image object request information:
> >> > Mar 25 22:08:12 alg kernel: [  598.301900] obj_request ffff88022409e1b8
> >> > Mar 25 22:08:12 alg kernel: [  598.301901]     ->object_name <(null)>
> >> > Mar 25 22:08:12 alg kernel: [  598.301902]     ->offset 0
> >> > Mar 25 22:08:12 alg kernel: [  598.301903]     ->length 8192
> >> > Mar 25 22:08:12 alg kernel: [  598.301904]     ->type 0x1
> >> > Mar 25 22:08:12 alg kernel: [  598.301905]     ->flags 0x3
> >> > Mar 25 22:08:12 alg kernel: [  598.301906]     ->which 4294967295
> >> > Mar 25 22:08:12 alg kernel: [  598.301906]     ->xferred 8192
> >> > Mar 25 22:08:12 alg kernel: [  598.301907]     ->result 0
> >> > Mar 25 22:08:12 alg kernel: [  598.301908] img_request ffff8802303bff10
> >> > Mar 25 22:08:12 alg kernel: [  598.301909]     ->snap 0xffff88022711f500
> >> > Mar 25 22:08:12 alg kernel: [  598.301910]     ->offset 4492079104
> >> > Mar 25 22:08:12 alg kernel: [  598.301911]     ->length 28672
> >> > Mar 25 22:08:12 alg kernel: [  598.301912]     ->flags 0x1
> >> > Mar 25 22:08:12 alg kernel: [  598.301913]     ->obj_request_count 0
> >> > Mar 25 22:08:12 alg kernel: [  598.301913]     ->next_completion 2
> >> > Mar 25 22:08:12 alg kernel: [  598.301914]     ->xferred 28672
> >> > Mar 25 22:08:12 alg kernel: [  598.301915]     ->result 0
> >> > Mar 25 22:08:12 alg kernel: [  598.301916]
> >> > Mar 25 22:08:12 alg kernel: [  598.301916] Assertion failure in rbd_img_obj_callback() at line 2159:
> >> > Mar 25 22:08:12 alg kernel: [  598.301916]
> >> > Mar 25 22:08:12 alg kernel: [  598.301916]      rbd_assert(0);
> >> > Mar 25 22:08:12 alg kernel: [  598.301916]
> >> > Mar 25 22:08:12 alg kernel: [  598.302093] ------------[ cut here ]------------
> >>
> >> Hmm...  Can you attach your drivers/block/rbd.c as of this third
> >> occurence?
> >>
> >> Thanks,
> >>
> >>                 Ilya
> >>
> >
> > Of course.
> 
> Sorry, I asked for the drivers/block/rbd.c C source file.
> 
> Thanks,
> 
>                 Ilya
> 

mmm the cluster seems to be in a really bad state now : all hosts are
hanging. Is it possible that mounting images without the rbd_assert(0)
broke some images ?


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Ilya Dryomov]

On Tue, Mar 25, 2014 at 11:41 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> mmm the cluster seems to be in a really bad state now : all hosts are
> hanging. Is it possible that mounting images without the rbd_assert(0)
> broke some images ?
>

I don't think so.  As far as I can tell all occurrences that you
reported tripped over one of the asserts.  It's probably just that for
some reason you are now hitting this bug much more frequently than once
a week.

Thanks,

                Ilya

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 23:49 +0200, Ilya Dryomov a écrit :
> On Tue, Mar 25, 2014 at 11:41 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> > mmm the cluster seems to be in a really bad state now : all hosts are
> > hanging. Is it possible that mounting images without the rbd_assert(0)
> > broke some images ?
> >
> 
> I don't think so.  As far as I can tell all occurrences that you
> reported tripped over one of the asserts.  It's probably just that for
> some reason you are now hitting this bug much more frequently than once
> a week.
> 
> Thanks,
> 
>                 Ilya
> --

Ok thanks, I'm «reassured».

At reboot VM are much more I/O loaded, because of cache flush. It's
probably the reason why it now hang often.

I have to wait a little between starting each VM.

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 22:54 +0100, Olivier Bonvalet a écrit :
> Le mardi 25 mars 2014 à 23:49 +0200, Ilya Dryomov a écrit :
> > On Tue, Mar 25, 2014 at 11:41 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> > > mmm the cluster seems to be in a really bad state now : all hosts are
> > > hanging. Is it possible that mounting images without the rbd_assert(0)
> > > broke some images ?
> > >
> > 
> > I don't think so.  As far as I can tell all occurrences that you
> > reported tripped over one of the asserts.  It's probably just that for
> > some reason you are now hitting this bug much more frequently than once
> > a week.
> > 
> > Thanks,
> > 
> >                 Ilya
> > --
> 
> Ok thanks, I'm «reassured».
> 
> At reboot VM are much more I/O loaded, because of cache flush. It's
> probably the reason why it now hang often.
> 
> I have to wait a little between starting each VM.
> 
> --

I now have this one very often (here 5 minutes after the host boot) :

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)>
Mar 25 23:14:45 rurkh kernel: [  330.054211]     ->offset 0
Mar 25 23:14:45 rurkh kernel: [  330.054213]     ->length 4096
Mar 25 23:14:45 rurkh kernel: [  330.054216]     ->type 0x1
Mar 25 23:14:45 rurkh kernel: [  330.054218]     ->flags 0x3
Mar 25 23:14:45 rurkh kernel: [  330.054220]     ->which 4294967295
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
Mar 25 23:14:45 rurkh kernel: [  330.054231]     ->offset 2508181504
Mar 25 23:14:45 rurkh kernel: [  330.054233]     ->length 16384
Mar 25 23:14:45 rurkh kernel: [  330.054235]     ->flags 0x0
Mar 25 23:14:45 rurkh kernel: [  330.054237]     ->obj_request_count 0
Mar 25 23:14:45 rurkh kernel: [  330.054239]     ->next_completion 2
Mar 25 23:14:45 rurkh kernel: [  330.054241]     ->xferred 16384
Mar 25 23:14:45 rurkh kernel: [  330.054243]     ->result 0
Mar 25 23:14:45 rurkh kernel: [  330.054247] 
Mar 25 23:14:45 rurkh kernel: [  330.054247] Assertion failure in rbd_img_obj_callback() at line 2159:
Mar 25 23:14:45 rurkh kernel: [  330.054247] 
Mar 25 23:14:45 rurkh kernel: [  330.054247] 	rbd_assert(0);
Mar 25 23:14:45 rurkh kernel: [  330.054247] 
Mar 25 23:14:45 rurkh kernel: [  330.054495] ------------[ cut here ]------------
Mar 25 23:14:45 rurkh kernel: [  330.054585] kernel BUG at drivers/block/rbd.c:2159!
Mar 25 23:14:45 rurkh kernel: [  330.054676] invalid opcode: 0000 [#1] SMP 
Mar 25 23:14:45 rurkh kernel: [  330.054874] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core evdev i2c_i801 lpc_ich mfd_core ioatdma shpchp wmi ipmi_si ipmi_msghandler ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common megaraid_sas isci ahci libsas libahci libata scsi_transport_sas ehci_pci ehci_hcd scsi_mod usbcore igb usb_common i2c_algo_bit ixgbe i2c_core dca ptp pps_core mdio
Mar 25 23:14:45 rurkh kernel: [  330.058433] CPU: 2 PID: 6365 Comm: kworker/2:3 Not tainted 3.13-dae-dom0 #22
Mar 25 23:14:45 rurkh kernel: [  330.058528] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
Mar 25 23:14:45 rurkh kernel: [  330.058659] Workqueue: ceph-msgr con_work [libceph]
Mar 25 23:14:45 rurkh kernel: [  330.058805] task: ffff88026da5b820 ti: ffff88025dfe2000 task.ti: ffff88025dfe2000
Mar 25 23:14:45 rurkh kernel: [  330.058922] RIP: e030:[<ffffffffa0309cd9>]  [<ffffffffa0309cd9>] rbd_img_obj_callback+0x282/0x523 [rbd]
Mar 25 23:14:45 rurkh kernel: [  330.059107] RSP: e02b:ffff88025dfe3ce8  EFLAGS: 00010082
Mar 25 23:14:45 rurkh kernel: [  330.059199] RAX: 000000000000004c RBX: ffff88025f3df058 RCX: 0000000000000007
Mar 25 23:14:45 rurkh kernel: [  330.059300] RDX: 0000000000000006 RSI: 0000000000000000 RDI: ffff88025dfe00a8
Mar 25 23:14:45 rurkh kernel: [  330.059397] RBP: ffff8802731f8448 R08: 0000000000000000 R09: 0000000000000000
Mar 25 23:14:45 rurkh kernel: [  330.059491] R10: 0000000000000000 R11: ffff88025f712d66 R12: 0000000000000001
Mar 25 23:14:45 rurkh kernel: [  330.059587] R13: 0000000000000000 R14: ffff88025f712ad0 R15: 0000000000000000
Mar 25 23:14:45 rurkh kernel: [  330.059689] FS:  00007f2fd8882700(0000) GS:ffff88027fe40000(0000) knlGS:0000000000000000
Mar 25 23:14:45 rurkh kernel: [  330.059807] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 25 23:14:45 rurkh kernel: [  330.059899] CR2: 00007f7a1e28f000 CR3: 000000000160c000 CR4: 0000000000042660
Mar 25 23:14:45 rurkh kernel: [  330.059997] Stack:
Mar 25 23:14:45 rurkh kernel: [  330.060086]  ffff8802731f8484 ffff8802730f2c45 ffffffffffffffff ffff8802730f2c10
Mar 25 23:14:45 rurkh kernel: [  330.060339]  ffff88025f712ac8 ffff8802703b4718 0000000000000000 ffff88025f712ad0
Mar 25 23:14:45 rurkh kernel: [  330.060573]  0000000000000000 ffffffffa02f5595 0000000000000015 ffff8802703b4770
Mar 25 23:14:45 rurkh kernel: [  330.060811] Call Trace:
Mar 25 23:14:45 rurkh kernel: [  330.060878]  [<ffffffffa02f5595>] ? dispatch+0x3e4/0x55e [libceph]
Mar 25 23:14:45 rurkh kernel: [  330.060954]  [<ffffffffa02f00fc>] ? con_work+0xf6e/0x1a65 [libceph]
Mar 25 23:14:45 rurkh kernel: [  330.061029]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
Mar 25 23:14:45 rurkh kernel: [  330.061098]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
Mar 25 23:14:45 rurkh kernel: [  330.061171]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
Mar 25 23:14:45 rurkh kernel: [  330.061243]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
Mar 25 23:14:45 rurkh kernel: [  330.061313]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
Mar 25 23:14:45 rurkh kernel: [  330.061385]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
Mar 25 23:14:45 rurkh kernel: [  330.061454]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Mar 25 23:14:45 rurkh kernel: [  330.061530]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
Mar 25 23:14:45 rurkh kernel: [  330.061606]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Mar 25 23:14:45 rurkh kernel: [  330.061677] Code: cc 30 a0 31 c0 e8 8b e4 05 e1 48 c7 c1 5c cd 30 a0 31 c0 ba 6f 08 00 00 48 c7 c6 80 da 30 a0 48 c7 c7 1f c1 30 a0 e8 6a e4 05 e1 <0f> 0b 41 8b 45 5c ff c8 39 43 40 41 0f 92 c5 48 8b 5b 30 41 ff 
Mar 25 23:14:45 rurkh kernel: [  330.064345] RIP  [<ffffffffa0309cd9>] rbd_img_obj_callback+0x282/0x523 [rbd]
Mar 25 23:14:45 rurkh kernel: [  330.064481]  RSP <ffff88025dfe3ce8>
Mar 25 23:14:45 rurkh kernel: [  330.064562] ---[ end trace 74103a003e0d553e ]---


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 05:17 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 22:54 +0100, Olivier Bonvalet a écrit :
>> Le mardi 25 mars 2014 à 23:49 +0200, Ilya Dryomov a écrit :
>>> On Tue, Mar 25, 2014 at 11:41 PM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
>>>> mmm the cluster seems to be in a really bad state now : all hosts are
>>>> hanging. Is it possible that mounting images without the rbd_assert(0)
>>>> broke some images ?
>>>>
>>>
>>> I don't think so.  As far as I can tell all occurrences that you
>>> reported tripped over one of the asserts.  It's probably just that for
>>> some reason you are now hitting this bug much more frequently than once
>>> a week.
>>>
>>> Thanks,
>>>
>>>                 Ilya
>>> --
>>
>> Ok thanks, I'm «reassured».
>>
>> At reboot VM are much more I/O loaded, because of cache flush. It's
>> probably the reason why it now hang often.
>>
>> I have to wait a little between starting each VM.
>>
>> --
> 
> I now have this one very often (here 5 minutes after the host boot) :

I am fairly sure this indicates a use-after-free scenario,
likely caused by something getting deleted before every
user was done with it.

I believe Ilya is done for the night; I'm going to spend some
time looking at this to try to determine the cause.  If you
are willing I'd love to have you try whatever fix I come up
with.  I'd rather find a fix than just collect more information,
but I may need to get more, we'll see.

Thank you for all your reports, they help a lot.

					-Alex

> 
> 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)>
> Mar 25 23:14:45 rurkh kernel: [  330.054211]     ->offset 0
> Mar 25 23:14:45 rurkh kernel: [  330.054213]     ->length 4096
> Mar 25 23:14:45 rurkh kernel: [  330.054216]     ->type 0x1
> Mar 25 23:14:45 rurkh kernel: [  330.054218]     ->flags 0x3
> Mar 25 23:14:45 rurkh kernel: [  330.054220]     ->which 4294967295
> 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
> Mar 25 23:14:45 rurkh kernel: [  330.054231]     ->offset 2508181504
> Mar 25 23:14:45 rurkh kernel: [  330.054233]     ->length 16384
> Mar 25 23:14:45 rurkh kernel: [  330.054235]     ->flags 0x0
> Mar 25 23:14:45 rurkh kernel: [  330.054237]     ->obj_request_count 0
> Mar 25 23:14:45 rurkh kernel: [  330.054239]     ->next_completion 2
> Mar 25 23:14:45 rurkh kernel: [  330.054241]     ->xferred 16384
> Mar 25 23:14:45 rurkh kernel: [  330.054243]     ->result 0
> Mar 25 23:14:45 rurkh kernel: [  330.054247] 
> Mar 25 23:14:45 rurkh kernel: [  330.054247] Assertion failure in rbd_img_obj_callback() at line 2159:
> Mar 25 23:14:45 rurkh kernel: [  330.054247] 
> Mar 25 23:14:45 rurkh kernel: [  330.054247] 	rbd_assert(0);
> Mar 25 23:14:45 rurkh kernel: [  330.054247] 
> Mar 25 23:14:45 rurkh kernel: [  330.054495] ------------[ cut here ]------------
> Mar 25 23:14:45 rurkh kernel: [  330.054585] kernel BUG at drivers/block/rbd.c:2159!
> Mar 25 23:14:45 rurkh kernel: [  330.054676] invalid opcode: 0000 [#1] SMP 
> Mar 25 23:14:45 rurkh kernel: [  330.054874] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core evdev i2c_i801 lpc_ich mfd_core ioatdma shpchp wmi ipmi_si ipmi_msghandler ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common megaraid_sas isci ahci libsas libahci libata scsi_transport_sas ehci_pci ehci_hcd scsi_mod usbcore igb usb_common i2c_algo_bit ixgbe i2c_core dca ptp pps_core mdio
> Mar 25 23:14:45 rurkh kernel: [  330.058433] CPU: 2 PID: 6365 Comm: kworker/2:3 Not tainted 3.13-dae-dom0 #22
> Mar 25 23:14:45 rurkh kernel: [  330.058528] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
> Mar 25 23:14:45 rurkh kernel: [  330.058659] Workqueue: ceph-msgr con_work [libceph]
> Mar 25 23:14:45 rurkh kernel: [  330.058805] task: ffff88026da5b820 ti: ffff88025dfe2000 task.ti: ffff88025dfe2000
> Mar 25 23:14:45 rurkh kernel: [  330.058922] RIP: e030:[<ffffffffa0309cd9>]  [<ffffffffa0309cd9>] rbd_img_obj_callback+0x282/0x523 [rbd]
> Mar 25 23:14:45 rurkh kernel: [  330.059107] RSP: e02b:ffff88025dfe3ce8  EFLAGS: 00010082
> Mar 25 23:14:45 rurkh kernel: [  330.059199] RAX: 000000000000004c RBX: ffff88025f3df058 RCX: 0000000000000007
> Mar 25 23:14:45 rurkh kernel: [  330.059300] RDX: 0000000000000006 RSI: 0000000000000000 RDI: ffff88025dfe00a8
> Mar 25 23:14:45 rurkh kernel: [  330.059397] RBP: ffff8802731f8448 R08: 0000000000000000 R09: 0000000000000000
> Mar 25 23:14:45 rurkh kernel: [  330.059491] R10: 0000000000000000 R11: ffff88025f712d66 R12: 0000000000000001
> Mar 25 23:14:45 rurkh kernel: [  330.059587] R13: 0000000000000000 R14: ffff88025f712ad0 R15: 0000000000000000
> Mar 25 23:14:45 rurkh kernel: [  330.059689] FS:  00007f2fd8882700(0000) GS:ffff88027fe40000(0000) knlGS:0000000000000000
> Mar 25 23:14:45 rurkh kernel: [  330.059807] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
> Mar 25 23:14:45 rurkh kernel: [  330.059899] CR2: 00007f7a1e28f000 CR3: 000000000160c000 CR4: 0000000000042660
> Mar 25 23:14:45 rurkh kernel: [  330.059997] Stack:
> Mar 25 23:14:45 rurkh kernel: [  330.060086]  ffff8802731f8484 ffff8802730f2c45 ffffffffffffffff ffff8802730f2c10
> Mar 25 23:14:45 rurkh kernel: [  330.060339]  ffff88025f712ac8 ffff8802703b4718 0000000000000000 ffff88025f712ad0
> Mar 25 23:14:45 rurkh kernel: [  330.060573]  0000000000000000 ffffffffa02f5595 0000000000000015 ffff8802703b4770
> Mar 25 23:14:45 rurkh kernel: [  330.060811] Call Trace:
> Mar 25 23:14:45 rurkh kernel: [  330.060878]  [<ffffffffa02f5595>] ? dispatch+0x3e4/0x55e [libceph]
> Mar 25 23:14:45 rurkh kernel: [  330.060954]  [<ffffffffa02f00fc>] ? con_work+0xf6e/0x1a65 [libceph]
> Mar 25 23:14:45 rurkh kernel: [  330.061029]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
> Mar 25 23:14:45 rurkh kernel: [  330.061098]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
> Mar 25 23:14:45 rurkh kernel: [  330.061171]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
> Mar 25 23:14:45 rurkh kernel: [  330.061243]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
> Mar 25 23:14:45 rurkh kernel: [  330.061313]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
> Mar 25 23:14:45 rurkh kernel: [  330.061385]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
> Mar 25 23:14:45 rurkh kernel: [  330.061454]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Mar 25 23:14:45 rurkh kernel: [  330.061530]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
> Mar 25 23:14:45 rurkh kernel: [  330.061606]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Mar 25 23:14:45 rurkh kernel: [  330.061677] Code: cc 30 a0 31 c0 e8 8b e4 05 e1 48 c7 c1 5c cd 30 a0 31 c0 ba 6f 08 00 00 48 c7 c6 80 da 30 a0 48 c7 c7 1f c1 30 a0 e8 6a e4 05 e1 <0f> 0b 41 8b 45 5c ff c8 39 43 40 41 0f 92 c5 48 8b 5b 30 41 ff 
> Mar 25 23:14:45 rurkh kernel: [  330.064345] RIP  [<ffffffffa0309cd9>] rbd_img_obj_callback+0x282/0x523 [rbd]
> Mar 25 23:14:45 rurkh kernel: [  330.064481]  RSP <ffff88025dfe3ce8>
> Mar 25 23:14:45 rurkh kernel: [  330.064562] ---[ end trace 74103a003e0d553e ]---
> 
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 17:46 -0500, Alex Elder a écrit :
> On 03/25/2014 05:17 PM, Olivier Bonvalet wrote:
> > 
> > I now have this one very often (here 5 minutes after the host boot) :
> 
> I am fairly sure this indicates a use-after-free scenario,
> likely caused by something getting deleted before every
> user was done with it.
> 
> I believe Ilya is done for the night; I'm going to spend some
> time looking at this to try to determine the cause.  If you
> are willing I'd love to have you try whatever fix I come up
> with.  I'd rather find a fix than just collect more information,
> but I may need to get more, we'll see.
> 
> Thank you for all your reports, they help a lot.
> 
> 					-Alex

Ok. I can apply some patch to help debug that yes.
I will try to reproduce on a different host, without customer data.

But I think I will stop here for the night too.

Thanks for your time,
Olivier

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 06:04 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 17:46 -0500, Alex Elder a écrit :
>> On 03/25/2014 05:17 PM, Olivier Bonvalet wrote:
>>>
>>> I now have this one very often (here 5 minutes after the host boot) :
>>
>> I am fairly sure this indicates a use-after-free scenario,
>> likely caused by something getting deleted before every
>> user was done with it.
>>
>> I believe Ilya is done for the night; I'm going to spend some
>> time looking at this to try to determine the cause.  If you
>> are willing I'd love to have you try whatever fix I come up
>> with.  I'd rather find a fix than just collect more information,
>> but I may need to get more, we'll see.
>>
>> Thank you for all your reports, they help a lot.
>>
>> 					-Alex
> 
> Ok. I can apply some patch to help debug that yes.
> I will try to reproduce on a different host, without customer data.
> 
> But I think I will stop here for the night too.
> 
> Thanks for your time,
> Olivier

Here's something that will provide a few more pieces of
information.  If you're around and you're able to try it
out it might confirm something had likely been destroyed.

I'll keep sending stuff as I come up with it (even though
I realize you may not be around until morning).

					-Alex


Index: b/drivers/block/rbd.c
===================================================================
--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2132,6 +2132,35 @@ static void rbd_img_obj_callback(struct
 	spin_lock_irq(&img_request->completion_lock);
 	if (which > img_request->next_completion)
 		goto out;
+	if (which != img_request->next_completion) {
+		printk("%s: bad image object request information:\n", __func__);
+		printk("obj_request %p\n", obj_request);
+		printk("    ->object_name <%s>\n", obj_request->object_name);
+		printk("    ->offset %llu\n", obj_request->offset);
+		printk("    ->length %llu\n", obj_request->length);
+		printk("    ->type 0x%x\n", (u32)obj_request->type);
+		printk("    ->flags 0x%lx\n", obj_request->flags);
+		printk("    ->img_request %p\n", obj_request->img_request);
+		printk("    ->which %u\n", obj_request->which);
+		printk("    ->xferred %llu\n", obj_request->xferred);
+		printk("    ->result %d\n", obj_request->result);
+		printk("    ->kref %d\n", atomic_read(&obj_request->kref));
+
+		printk("img_request %p\n", img_request);
+		printk("    ->snap 0x%016llx\n", img_request->snap_id);
+		printk("    ->offset %llu\n", img_request->offset);
+		printk("    ->length %llu\n", img_request->length);
+		printk("    ->flags 0x%lx\n", img_request->flags);
+		printk("    ->obj_request_count %u\n",
+			img_request->obj_request_count);
+		printk("    ->next_completion %u\n",
+			img_request->next_completion);
+		printk("    ->xferred %llu\n", img_request->xferred);
+		printk("    ->result %d\n", img_request->result);
+		printk("    ->obj_requests head %p\n",
+			img_request->obj_requests.next);
+		printk("    ->kref %d\n", atomic_read(&img_request->kref));
+	}
 	rbd_assert(which == img_request->next_completion);

 	for_each_obj_request_from(img_request, obj_request) {

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 19:00 -0500, Alex Elder a écrit :
> On 03/25/2014 06:04 PM, Olivier Bonvalet wrote:
> > Le mardi 25 mars 2014 à 17:46 -0500, Alex Elder a écrit :
> >> On 03/25/2014 05:17 PM, Olivier Bonvalet wrote:
> >>>
> >>> I now have this one very often (here 5 minutes after the host boot) :
> >>
> >> I am fairly sure this indicates a use-after-free scenario,
> >> likely caused by something getting deleted before every
> >> user was done with it.
> >>
> >> I believe Ilya is done for the night; I'm going to spend some
> >> time looking at this to try to determine the cause.  If you
> >> are willing I'd love to have you try whatever fix I come up
> >> with.  I'd rather find a fix than just collect more information,
> >> but I may need to get more, we'll see.
> >>
> >> Thank you for all your reports, they help a lot.
> >>
> >> 					-Alex
> > 
> > Ok. I can apply some patch to help debug that yes.
> > I will try to reproduce on a different host, without customer data.
> > 
> > But I think I will stop here for the night too.
> > 
> > Thanks for your time,
> > Olivier
> 
> Here's something that will provide a few more pieces of
> information.  If you're around and you're able to try it
> out it might confirm something had likely been destroyed.
> 
> I'll keep sending stuff as I come up with it (even though
> I realize you may not be around until morning).
> 
> 					-Alex
> 
> 
> Index: b/drivers/block/rbd.c
> ===================================================================
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -2132,6 +2132,35 @@ static void rbd_img_obj_callback(struct
>  	spin_lock_irq(&img_request->completion_lock);
>  	if (which > img_request->next_completion)
>  		goto out;
> +	if (which != img_request->next_completion) {
> +		printk("%s: bad image object request information:\n", __func__);
> +		printk("obj_request %p\n", obj_request);
> +		printk("    ->object_name <%s>\n", obj_request->object_name);
> +		printk("    ->offset %llu\n", obj_request->offset);
> +		printk("    ->length %llu\n", obj_request->length);
> +		printk("    ->type 0x%x\n", (u32)obj_request->type);
> +		printk("    ->flags 0x%lx\n", obj_request->flags);
> +		printk("    ->img_request %p\n", obj_request->img_request);
> +		printk("    ->which %u\n", obj_request->which);
> +		printk("    ->xferred %llu\n", obj_request->xferred);
> +		printk("    ->result %d\n", obj_request->result);
> +		printk("    ->kref %d\n", atomic_read(&obj_request->kref));
> +
> +		printk("img_request %p\n", img_request);
> +		printk("    ->snap 0x%016llx\n", img_request->snap_id);
> +		printk("    ->offset %llu\n", img_request->offset);
> +		printk("    ->length %llu\n", img_request->length);
> +		printk("    ->flags 0x%lx\n", img_request->flags);
> +		printk("    ->obj_request_count %u\n",
> +			img_request->obj_request_count);
> +		printk("    ->next_completion %u\n",
> +			img_request->next_completion);
> +		printk("    ->xferred %llu\n", img_request->xferred);
> +		printk("    ->result %d\n", img_request->result);
> +		printk("    ->obj_requests head %p\n",
> +			img_request->obj_requests.next);
> +		printk("    ->kref %d\n", atomic_read(&img_request->kref));
> +	}
>  	rbd_assert(which == img_request->next_completion);
> 
>  	for_each_obj_request_from(img_request, obj_request) {
> 
> 

Thanks for your patch.

This is an output of a crash case :

Mar 26 02:31:18 alg kernel: [  965.366895] rbd_img_obj_callback: bad image object request information:
Mar 26 02:31:18 alg kernel: [  965.366905] obj_request ffff880224bc9528
Mar 26 02:31:18 alg kernel: [  965.366909]     ->object_name <(null)>
Mar 26 02:31:18 alg kernel: [  965.366913]     ->offset 0
Mar 26 02:31:18 alg kernel: [  965.366917]     ->length 4096
Mar 26 02:31:18 alg kernel: [  965.366921]     ->type 0x1
Mar 26 02:31:18 alg kernel: [  965.366925]     ->flags 0x3
Mar 26 02:31:18 alg kernel: [  965.366929]     ->img_request           (null)
Mar 26 02:31:18 alg kernel: [  965.366933]     ->which 4294967295
Mar 26 02:31:18 alg kernel: [  965.366936]     ->xferred 4096
Mar 26 02:31:18 alg kernel: [  965.366940]     ->result 0
Mar 26 02:31:18 alg kernel: [  965.366943]     ->kref 0
Mar 26 02:31:18 alg kernel: [  965.366947] img_request ffff880222f4fb50
Mar 26 02:31:18 alg kernel: [  965.366950]     ->snap 0xfffffffffffffffe
Mar 26 02:31:18 alg kernel: [  965.366954]     ->offset 1417662464
Mar 26 02:31:18 alg kernel: [  965.366957]     ->length 16384
Mar 26 02:31:18 alg kernel: [  965.366960]     ->flags 0x0
Mar 26 02:31:18 alg kernel: [  965.366963]     ->obj_request_count 0
Mar 26 02:31:18 alg kernel: [  965.366966]     ->next_completion 2
Mar 26 02:31:18 alg kernel: [  965.366969]     ->xferred 16384
Mar 26 02:31:18 alg kernel: [  965.366973]     ->result 0
Mar 26 02:31:18 alg kernel: [  965.366976]     ->obj_requests head ffff880222f4fbb0
Mar 26 02:31:18 alg kernel: [  965.366980]     ->kref 0
Mar 26 02:31:18 alg kernel: [  965.366985] 
Mar 26 02:31:18 alg kernel: [  965.366985] Assertion failure in rbd_img_obj_callback() at line 2165:
Mar 26 02:31:18 alg kernel: [  965.366985] 
Mar 26 02:31:18 alg kernel: [  965.366985] 	rbd_assert(which == img_request->next_completion);
Mar 26 02:31:18 alg kernel: [  965.366985] 
Mar 26 02:31:18 alg kernel: [  965.367185] ------------[ cut here ]------------
Mar 26 02:31:18 alg kernel: [  965.367241] kernel BUG at drivers/block/rbd.c:2165!


I hope it can help.


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mercredi 26 mars 2014 à 02:33 +0100, Olivier Bonvalet a écrit :
> Thanks for your patch.
> 
> This is an output of a crash case :
> 
> Mar 26 02:31:18 alg kernel: [  965.366895] rbd_img_obj_callback: bad image object request information:
> Mar 26 02:31:18 alg kernel: [  965.366905] obj_request ffff880224bc9528
> Mar 26 02:31:18 alg kernel: [  965.366909]     ->object_name <(null)>
> Mar 26 02:31:18 alg kernel: [  965.366913]     ->offset 0
> Mar 26 02:31:18 alg kernel: [  965.366917]     ->length 4096
> Mar 26 02:31:18 alg kernel: [  965.366921]     ->type 0x1
> Mar 26 02:31:18 alg kernel: [  965.366925]     ->flags 0x3
> Mar 26 02:31:18 alg kernel: [  965.366929]     ->img_request           (null)
> Mar 26 02:31:18 alg kernel: [  965.366933]     ->which 4294967295
> Mar 26 02:31:18 alg kernel: [  965.366936]     ->xferred 4096
> Mar 26 02:31:18 alg kernel: [  965.366940]     ->result 0
> Mar 26 02:31:18 alg kernel: [  965.366943]     ->kref 0
> Mar 26 02:31:18 alg kernel: [  965.366947] img_request ffff880222f4fb50
> Mar 26 02:31:18 alg kernel: [  965.366950]     ->snap 0xfffffffffffffffe
> Mar 26 02:31:18 alg kernel: [  965.366954]     ->offset 1417662464
> Mar 26 02:31:18 alg kernel: [  965.366957]     ->length 16384
> Mar 26 02:31:18 alg kernel: [  965.366960]     ->flags 0x0
> Mar 26 02:31:18 alg kernel: [  965.366963]     ->obj_request_count 0
> Mar 26 02:31:18 alg kernel: [  965.366966]     ->next_completion 2
> Mar 26 02:31:18 alg kernel: [  965.366969]     ->xferred 16384
> Mar 26 02:31:18 alg kernel: [  965.366973]     ->result 0
> Mar 26 02:31:18 alg kernel: [  965.366976]     ->obj_requests head ffff880222f4fbb0
> Mar 26 02:31:18 alg kernel: [  965.366980]     ->kref 0
> Mar 26 02:31:18 alg kernel: [  965.366985] 
> Mar 26 02:31:18 alg kernel: [  965.366985] Assertion failure in rbd_img_obj_callback() at line 2165:
> Mar 26 02:31:18 alg kernel: [  965.366985] 
> Mar 26 02:31:18 alg kernel: [  965.366985] 	rbd_assert(which == img_request->next_completion);
> Mar 26 02:31:18 alg kernel: [  965.366985] 
> Mar 26 02:31:18 alg kernel: [  965.367185] ------------[ cut here ]------------
> Mar 26 02:31:18 alg kernel: [  965.367241] kernel BUG at drivers/block/rbd.c:2165!
> 
> 
> I hope it can help.
> 
> 
> --

and a second one, very similar :

Mar 26 02:48:27 alg kernel: [  681.167833] rbd_img_obj_callback: bad image object request information:
Mar 26 02:48:27 alg kernel: [  681.167836] obj_request ffff88022e1e2828
Mar 26 02:48:27 alg kernel: [  681.167837]     ->object_name <(null)>
Mar 26 02:48:27 alg kernel: [  681.167838]     ->offset 0
Mar 26 02:48:27 alg kernel: [  681.167839]     ->length 4096
Mar 26 02:48:27 alg kernel: [  681.167840]     ->type 0x1
Mar 26 02:48:27 alg kernel: [  681.167840]     ->flags 0x3
Mar 26 02:48:27 alg kernel: [  681.167841]     ->img_request           (null)
Mar 26 02:48:27 alg kernel: [  681.167842]     ->which 4294967295
Mar 26 02:48:27 alg kernel: [  681.167843]     ->xferred 4096
Mar 26 02:48:27 alg kernel: [  681.167844]     ->result 0
Mar 26 02:48:27 alg kernel: [  681.167844]     ->kref 0
Mar 26 02:48:27 alg kernel: [  681.167845] img_request ffff88021f555f10
Mar 26 02:48:27 alg kernel: [  681.167846]     ->snap 0xfffffffffffffffe
Mar 26 02:48:27 alg kernel: [  681.167847]     ->offset 28072464384
Mar 26 02:48:27 alg kernel: [  681.167847]     ->length 16384
Mar 26 02:48:27 alg kernel: [  681.167848]     ->flags 0x0
Mar 26 02:48:27 alg kernel: [  681.167849]     ->obj_request_count 0
Mar 26 02:48:27 alg kernel: [  681.167850]     ->next_completion 2
Mar 26 02:48:27 alg kernel: [  681.167850]     ->xferred 16384
Mar 26 02:48:27 alg kernel: [  681.167851]     ->result 0
Mar 26 02:48:27 alg kernel: [  681.167852]     ->obj_requests head ffff88021f555f70
Mar 26 02:48:27 alg kernel: [  681.167853]     ->kref 0
Mar 26 02:48:27 alg kernel: [  681.167854] 
Mar 26 02:48:27 alg kernel: [  681.167854] Assertion failure in rbd_img_obj_callback() at line 2165:
Mar 26 02:48:27 alg kernel: [  681.167854] 
Mar 26 02:48:27 alg kernel: [  681.167854] 	rbd_assert(which == img_request->next_completion);
Mar 26 02:48:27 alg kernel: [  681.167854] 
Mar 26 02:48:27 alg kernel: [  681.168117] ------------[ cut here ]------------
Mar 26 02:48:27 alg kernel: [  681.168211] kernel BUG at drivers/block/rbd.c:2165!


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 08:50 PM, Olivier Bonvalet wrote:
> Le mercredi 26 mars 2014 à 02:33 +0100, Olivier Bonvalet a écrit :
>> Thanks for your patch.
>>
>> This is an output of a crash case :
>>
>> Mar 26 02:31:18 alg kernel: [  965.366895] rbd_img_obj_callback: bad image object request information:
>> Mar 26 02:31:18 alg kernel: [  965.366905] obj_request ffff880224bc9528
>> Mar 26 02:31:18 alg kernel: [  965.366909]     ->object_name <(null)>
>> Mar 26 02:31:18 alg kernel: [  965.366913]     ->offset 0
>> Mar 26 02:31:18 alg kernel: [  965.366917]     ->length 4096
>> Mar 26 02:31:18 alg kernel: [  965.366921]     ->type 0x1
>> Mar 26 02:31:18 alg kernel: [  965.366925]     ->flags 0x3
>> Mar 26 02:31:18 alg kernel: [  965.366929]     ->img_request           (null)
>> Mar 26 02:31:18 alg kernel: [  965.366933]     ->which 4294967295
>> Mar 26 02:31:18 alg kernel: [  965.366936]     ->xferred 4096
>> Mar 26 02:31:18 alg kernel: [  965.366940]     ->result 0
>> Mar 26 02:31:18 alg kernel: [  965.366943]     ->kref 0
>> Mar 26 02:31:18 alg kernel: [  965.366947] img_request ffff880222f4fb50
>> Mar 26 02:31:18 alg kernel: [  965.366950]     ->snap 0xfffffffffffffffe
>> Mar 26 02:31:18 alg kernel: [  965.366954]     ->offset 1417662464
>> Mar 26 02:31:18 alg kernel: [  965.366957]     ->length 16384
>> Mar 26 02:31:18 alg kernel: [  965.366960]     ->flags 0x0
>> Mar 26 02:31:18 alg kernel: [  965.366963]     ->obj_request_count 0
>> Mar 26 02:31:18 alg kernel: [  965.366966]     ->next_completion 2
>> Mar 26 02:31:18 alg kernel: [  965.366969]     ->xferred 16384
>> Mar 26 02:31:18 alg kernel: [  965.366973]     ->result 0
>> Mar 26 02:31:18 alg kernel: [  965.366976]     ->obj_requests head ffff880222f4fbb0
>> Mar 26 02:31:18 alg kernel: [  965.366980]     ->kref 0
>> Mar 26 02:31:18 alg kernel: [  965.366985] 
>> Mar 26 02:31:18 alg kernel: [  965.366985] Assertion failure in rbd_img_obj_callback() at line 2165:
>> Mar 26 02:31:18 alg kernel: [  965.366985] 
>> Mar 26 02:31:18 alg kernel: [  965.366985] 	rbd_assert(which == img_request->next_completion);
>> Mar 26 02:31:18 alg kernel: [  965.366985] 
>> Mar 26 02:31:18 alg kernel: [  965.367185] ------------[ cut here ]------------
>> Mar 26 02:31:18 alg kernel: [  965.367241] kernel BUG at drivers/block/rbd.c:2165!
>>
>>
>> I hope it can help.
>>
>>


Thanks for sending these.

> 
> and a second one, very similar :
> 
> Mar 26 02:48:27 alg kernel: [  681.167833] rbd_img_obj_callback: bad image object request information:
> Mar 26 02:48:27 alg kernel: [  681.167836] obj_request ffff88022e1e2828
> Mar 26 02:48:27 alg kernel: [  681.167837]     ->object_name <(null)>
> Mar 26 02:48:27 alg kernel: [  681.167838]     ->offset 0
> Mar 26 02:48:27 alg kernel: [  681.167839]     ->length 4096
> Mar 26 02:48:27 alg kernel: [  681.167840]     ->type 0x1
> Mar 26 02:48:27 alg kernel: [  681.167840]     ->flags 0x3
> Mar 26 02:48:27 alg kernel: [  681.167841]     ->img_request           (null)
> Mar 26 02:48:27 alg kernel: [  681.167842]     ->which 4294967295
> Mar 26 02:48:27 alg kernel: [  681.167843]     ->xferred 4096
> Mar 26 02:48:27 alg kernel: [  681.167844]     ->result 0
> Mar 26 02:48:27 alg kernel: [  681.167844]     ->kref 0

This confirms the reference count of the object request has gone
to zero.  This object request has already been destroyed (yet
we're handling a callback for it).

> Mar 26 02:48:27 alg kernel: [  681.167845] img_request ffff88021f555f10
> Mar 26 02:48:27 alg kernel: [  681.167846]     ->snap 0xfffffffffffffffe
> Mar 26 02:48:27 alg kernel: [  681.167847]     ->offset 28072464384
> Mar 26 02:48:27 alg kernel: [  681.167847]     ->length 16384
> Mar 26 02:48:27 alg kernel: [  681.167848]     ->flags 0x0
> Mar 26 02:48:27 alg kernel: [  681.167849]     ->obj_request_count 0
> Mar 26 02:48:27 alg kernel: [  681.167850]     ->next_completion 2
> Mar 26 02:48:27 alg kernel: [  681.167850]     ->xferred 16384
> Mar 26 02:48:27 alg kernel: [  681.167851]     ->result 0
> Mar 26 02:48:27 alg kernel: [  681.167852]     ->obj_requests head ffff88021f555f70

The object request list is empty.

> Mar 26 02:48:27 alg kernel: [  681.167853]     ->kref 0

This confirms the reference count of the image request has gone
to zero.  So not only has the object request already completed,
the image request has as well.

I'm almost done composing a very large e-mail with some detailed
analysis.  No answer quite yet, but I am certain that we're
getting duplicate callbacks on the second object request of
an image request that spans two objects.  That should help
narrow the search for the root cause.

					-Alex

> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.167854] Assertion failure in rbd_img_obj_callback() at line 2165:
> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.167854] 	rbd_assert(which == img_request->next_completion);
> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.168117] ------------[ cut here ]------------
> Mar 26 02:48:27 alg kernel: [  681.168211] kernel BUG at drivers/block/rbd.c:2165!
> 
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 20:55 -0500, Alex Elder a écrit :
> On 03/25/2014 08:50 PM, Olivier Bonvalet wrote:
> > Le mercredi 26 mars 2014 à 02:33 +0100, Olivier Bonvalet a écrit :
> >> Thanks for your patch.
> >>
> >> This is an output of a crash case :
> >>
> >> Mar 26 02:31:18 alg kernel: [  965.366895] rbd_img_obj_callback: bad image object request information:
> >> Mar 26 02:31:18 alg kernel: [  965.366905] obj_request ffff880224bc9528
> >> Mar 26 02:31:18 alg kernel: [  965.366909]     ->object_name <(null)>
> >> Mar 26 02:31:18 alg kernel: [  965.366913]     ->offset 0
> >> Mar 26 02:31:18 alg kernel: [  965.366917]     ->length 4096
> >> Mar 26 02:31:18 alg kernel: [  965.366921]     ->type 0x1
> >> Mar 26 02:31:18 alg kernel: [  965.366925]     ->flags 0x3
> >> Mar 26 02:31:18 alg kernel: [  965.366929]     ->img_request           (null)
> >> Mar 26 02:31:18 alg kernel: [  965.366933]     ->which 4294967295
> >> Mar 26 02:31:18 alg kernel: [  965.366936]     ->xferred 4096
> >> Mar 26 02:31:18 alg kernel: [  965.366940]     ->result 0
> >> Mar 26 02:31:18 alg kernel: [  965.366943]     ->kref 0
> >> Mar 26 02:31:18 alg kernel: [  965.366947] img_request ffff880222f4fb50
> >> Mar 26 02:31:18 alg kernel: [  965.366950]     ->snap 0xfffffffffffffffe
> >> Mar 26 02:31:18 alg kernel: [  965.366954]     ->offset 1417662464
> >> Mar 26 02:31:18 alg kernel: [  965.366957]     ->length 16384
> >> Mar 26 02:31:18 alg kernel: [  965.366960]     ->flags 0x0
> >> Mar 26 02:31:18 alg kernel: [  965.366963]     ->obj_request_count 0
> >> Mar 26 02:31:18 alg kernel: [  965.366966]     ->next_completion 2
> >> Mar 26 02:31:18 alg kernel: [  965.366969]     ->xferred 16384
> >> Mar 26 02:31:18 alg kernel: [  965.366973]     ->result 0
> >> Mar 26 02:31:18 alg kernel: [  965.366976]     ->obj_requests head ffff880222f4fbb0
> >> Mar 26 02:31:18 alg kernel: [  965.366980]     ->kref 0
> >> Mar 26 02:31:18 alg kernel: [  965.366985] 
> >> Mar 26 02:31:18 alg kernel: [  965.366985] Assertion failure in rbd_img_obj_callback() at line 2165:
> >> Mar 26 02:31:18 alg kernel: [  965.366985] 
> >> Mar 26 02:31:18 alg kernel: [  965.366985] 	rbd_assert(which == img_request->next_completion);
> >> Mar 26 02:31:18 alg kernel: [  965.366985] 
> >> Mar 26 02:31:18 alg kernel: [  965.367185] ------------[ cut here ]------------
> >> Mar 26 02:31:18 alg kernel: [  965.367241] kernel BUG at drivers/block/rbd.c:2165!
> >>
> >>
> >> I hope it can help.
> >>
> >>
> 
> 
> Thanks for sending these.
> 
> > 
> > and a second one, very similar :
> > 
> > Mar 26 02:48:27 alg kernel: [  681.167833] rbd_img_obj_callback: bad image object request information:
> > Mar 26 02:48:27 alg kernel: [  681.167836] obj_request ffff88022e1e2828
> > Mar 26 02:48:27 alg kernel: [  681.167837]     ->object_name <(null)>
> > Mar 26 02:48:27 alg kernel: [  681.167838]     ->offset 0
> > Mar 26 02:48:27 alg kernel: [  681.167839]     ->length 4096
> > Mar 26 02:48:27 alg kernel: [  681.167840]     ->type 0x1
> > Mar 26 02:48:27 alg kernel: [  681.167840]     ->flags 0x3
> > Mar 26 02:48:27 alg kernel: [  681.167841]     ->img_request           (null)
> > Mar 26 02:48:27 alg kernel: [  681.167842]     ->which 4294967295
> > Mar 26 02:48:27 alg kernel: [  681.167843]     ->xferred 4096
> > Mar 26 02:48:27 alg kernel: [  681.167844]     ->result 0
> > Mar 26 02:48:27 alg kernel: [  681.167844]     ->kref 0
> 
> This confirms the reference count of the object request has gone
> to zero.  This object request has already been destroyed (yet
> we're handling a callback for it).
> 
> > Mar 26 02:48:27 alg kernel: [  681.167845] img_request ffff88021f555f10
> > Mar 26 02:48:27 alg kernel: [  681.167846]     ->snap 0xfffffffffffffffe
> > Mar 26 02:48:27 alg kernel: [  681.167847]     ->offset 28072464384
> > Mar 26 02:48:27 alg kernel: [  681.167847]     ->length 16384
> > Mar 26 02:48:27 alg kernel: [  681.167848]     ->flags 0x0
> > Mar 26 02:48:27 alg kernel: [  681.167849]     ->obj_request_count 0
> > Mar 26 02:48:27 alg kernel: [  681.167850]     ->next_completion 2
> > Mar 26 02:48:27 alg kernel: [  681.167850]     ->xferred 16384
> > Mar 26 02:48:27 alg kernel: [  681.167851]     ->result 0
> > Mar 26 02:48:27 alg kernel: [  681.167852]     ->obj_requests head ffff88021f555f70
> 
> The object request list is empty.
> 
> > Mar 26 02:48:27 alg kernel: [  681.167853]     ->kref 0
> 
> This confirms the reference count of the image request has gone
> to zero.  So not only has the object request already completed,
> the image request has as well.
> 
> I'm almost done composing a very large e-mail with some detailed
> analysis.  No answer quite yet, but I am certain that we're
> getting duplicate callbacks on the second object request of
> an image request that spans two objects.  That should help
> narrow the search for the root cause.
> 
> 					-Alex

Thanks again to took time to analyze that problem.

All my RBD images have daily snapshots, can this bug be related to
snapshots ?

Maybe it's a stupid question, but is there a workaround that I could use
to reduce that problem in production, until a proper fix is found ?


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 09:40 PM, Olivier Bonvalet wrote:
> Thanks again to took time to analyze that problem.
> 
> All my RBD images have daily snapshots, can this bug be related to
> snapshots ?
> 
> Maybe it's a stupid question, but is there a workaround that I could use
> to reduce that problem in production, until a proper fix is found ?

I don't believe this has anything to do with snapshots.

And I wish I knew a workaround, but unfortunately I
don't know of one.  Once I understand the problem (I'm
getting close) I might have one, but at that point I'll
probably have a fix.

I'll try to find a fix as soon as I can.

					-Alex

PS  I thought you said you were going to stop for the night!

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 21:42 -0500, Alex Elder a écrit :
> PS  I thought you said you were going to stop for the night!

Yes, I would love ! But my phone doesn't stop ring about ceph crash :D

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 03/25/2014 09:45 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 21:42 -0500, Alex Elder a écrit :
>> PS  I thought you said you were going to stop for the night!
> 
> Yes, I would love ! But my phone doesn't stop ring about ceph crash :D
> 

OK, one more thing to try and I'm going to bed.

I'm hoping that an image request spanning multiple objects
is an unusual case, enough so that the following won't
overwhelm with output.  I'd avoid putting it on a production
system (that's the case for all this testing, really) if
possible.

Basically I'm trying to catch an image object request being
either submitted more than once, or completing more than
once.  So if an image request has more than one object
request I produce some informative output.

This patch fixes two warnings in the previous debug patch,
and adds to it (so use it instead of the last one).

If you get a chance to try this I'll want to see the output.
But first, I shall sleep.

Thank you.

					-Alex

Index: b/drivers/block/rbd.c
===================================================================
--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -1484,6 +1484,10 @@ static void rbd_img_request_complete(str
 			xferred += obj_request->xferred;
 		img_request->xferred = xferred;
 	}
+	if (img_request->obj_request_count > 1)
+		printk("%s: img_request %p count %u result %d xferred %llu\n",
+			__func__, img_request, img_request->obj_request_count,
+			img_request->result, img_request->xferred);

 	if (img_request->callback)
 		img_request->callback(img_request);
@@ -2129,9 +2133,43 @@ static void rbd_img_obj_callback(struct
 	rbd_assert(which != BAD_WHICH);
 	rbd_assert(which < img_request->obj_request_count);

+	if (img_request->obj_request_count > 1)
+		printk("%s: obj_request %p (%llu/%llu)\n", __func__,
+			obj_request, obj_request->offset, obj_request->length);
 	spin_lock_irq(&img_request->completion_lock);
 	if (which > img_request->next_completion)
 		goto out;
+	if (which != img_request->next_completion) {
+		printk("%s: bad image object request information:\n", __func__);
+		printk("obj_request %p\n", obj_request);
+		printk("    ->object_name <%s>\n", obj_request->object_name);
+		printk("    ->offset %llu\n", obj_request->offset);
+		printk("    ->length %llu\n", obj_request->length);
+		printk("    ->type 0x%x\n", (u32)obj_request->type);
+		printk("    ->flags 0x%lx\n", obj_request->flags);
+		printk("    ->img_request %p\n", obj_request->img_request);
+		printk("    ->which %u\n", obj_request->which);
+		printk("    ->xferred %llu\n", obj_request->xferred);
+		printk("    ->result %d\n", obj_request->result);
+		printk("    ->kref %d\n",
+			atomic_read(&obj_request->kref.refcount));
+
+		printk("img_request %p\n", img_request);
+		printk("    ->snap 0x%016llx\n", img_request->snap_id);
+		printk("    ->offset %llu\n", img_request->offset);
+		printk("    ->length %llu\n", img_request->length);
+		printk("    ->flags 0x%lx\n", img_request->flags);
+		printk("    ->obj_request_count %u\n",
+			img_request->obj_request_count);
+		printk("    ->next_completion %u\n",
+			img_request->next_completion);
+		printk("    ->xferred %llu\n", img_request->xferred);
+		printk("    ->result %d\n", img_request->result);
+		printk("    ->obj_requests head %p\n",
+			img_request->obj_requests.next);
+		printk("    ->kref %d\n",
+			atomic_read(&img_request->kref.refcount));
+	}
 	rbd_assert(which == img_request->next_completion);

 	for_each_obj_request_from(img_request, obj_request) {
@@ -2697,11 +2735,21 @@ static int rbd_img_request_submit(struct
 {
 	struct rbd_obj_request *obj_request;
 	struct rbd_obj_request *next_obj_request;
+	bool verbose = false;

 	dout("%s: img %p\n", __func__, img_request);
+	if (img_request->obj_request_count > 1) {
+		printk("%s: img_request %p count %u (%llu/%llu)\n", __func__,
+			img_request, img_request->offset, img_request->length);
+	    	verbose = true;
+	}
 	for_each_obj_request_safe(img_request, obj_request, next_obj_request) {
 		int ret;

+		if (verbose)
+			printk("%s: obj_request %p (%llu/%llu)\n", __func__,
+				obj_request, obj_request->offset,
+				obj_request->length);
 		ret = rbd_img_obj_request_submit(obj_request);
 		if (ret)
 			return ret;

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 22:54 -0500, Alex Elder a écrit :
> On 03/25/2014 09:45 PM, Olivier Bonvalet wrote:
> > Le mardi 25 mars 2014 à 21:42 -0500, Alex Elder a écrit :
> >> PS  I thought you said you were going to stop for the night!
> > 
> > Yes, I would love ! But my phone doesn't stop ring about ceph crash :D
> > 
> 
> OK, one more thing to try and I'm going to bed.
> 
> I'm hoping that an image request spanning multiple objects
> is an unusual case, enough so that the following won't
> overwhelm with output.  I'd avoid putting it on a production
> system (that's the case for all this testing, really) if
> possible.
> 
> Basically I'm trying to catch an image object request being
> either submitted more than once, or completing more than
> once.  So if an image request has more than one object
> request I produce some informative output.
> 
> This patch fixes two warnings in the previous debug patch,
> and adds to it (so use it instead of the last one).
> 
> If you get a chance to try this I'll want to see the output.
> But first, I shall sleep.
> 
> Thank you.
> 
> 					-Alex
> 
> Index: b/drivers/block/rbd.c
> ===================================================================
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -1484,6 +1484,10 @@ static void rbd_img_request_complete(str
>  			xferred += obj_request->xferred;
>  		img_request->xferred = xferred;
>  	}
> +	if (img_request->obj_request_count > 1)
> +		printk("%s: img_request %p count %u result %d xferred %llu\n",
> +			__func__, img_request, img_request->obj_request_count,
> +			img_request->result, img_request->xferred);
> 
>  	if (img_request->callback)
>  		img_request->callback(img_request);
> @@ -2129,9 +2133,43 @@ static void rbd_img_obj_callback(struct
>  	rbd_assert(which != BAD_WHICH);
>  	rbd_assert(which < img_request->obj_request_count);
> 
> +	if (img_request->obj_request_count > 1)
> +		printk("%s: obj_request %p (%llu/%llu)\n", __func__,
> +			obj_request, obj_request->offset, obj_request->length);
>  	spin_lock_irq(&img_request->completion_lock);
>  	if (which > img_request->next_completion)
>  		goto out;
> +	if (which != img_request->next_completion) {
> +		printk("%s: bad image object request information:\n", __func__);
> +		printk("obj_request %p\n", obj_request);
> +		printk("    ->object_name <%s>\n", obj_request->object_name);
> +		printk("    ->offset %llu\n", obj_request->offset);
> +		printk("    ->length %llu\n", obj_request->length);
> +		printk("    ->type 0x%x\n", (u32)obj_request->type);
> +		printk("    ->flags 0x%lx\n", obj_request->flags);
> +		printk("    ->img_request %p\n", obj_request->img_request);
> +		printk("    ->which %u\n", obj_request->which);
> +		printk("    ->xferred %llu\n", obj_request->xferred);
> +		printk("    ->result %d\n", obj_request->result);
> +		printk("    ->kref %d\n",
> +			atomic_read(&obj_request->kref.refcount));
> +
> +		printk("img_request %p\n", img_request);
> +		printk("    ->snap 0x%016llx\n", img_request->snap_id);
> +		printk("    ->offset %llu\n", img_request->offset);
> +		printk("    ->length %llu\n", img_request->length);
> +		printk("    ->flags 0x%lx\n", img_request->flags);
> +		printk("    ->obj_request_count %u\n",
> +			img_request->obj_request_count);
> +		printk("    ->next_completion %u\n",
> +			img_request->next_completion);
> +		printk("    ->xferred %llu\n", img_request->xferred);
> +		printk("    ->result %d\n", img_request->result);
> +		printk("    ->obj_requests head %p\n",
> +			img_request->obj_requests.next);
> +		printk("    ->kref %d\n",
> +			atomic_read(&img_request->kref.refcount));
> +	}
>  	rbd_assert(which == img_request->next_completion);
> 
>  	for_each_obj_request_from(img_request, obj_request) {
> @@ -2697,11 +2735,21 @@ static int rbd_img_request_submit(struct
>  {
>  	struct rbd_obj_request *obj_request;
>  	struct rbd_obj_request *next_obj_request;
> +	bool verbose = false;
> 
>  	dout("%s: img %p\n", __func__, img_request);
> +	if (img_request->obj_request_count > 1) {
> +		printk("%s: img_request %p count %u (%llu/%llu)\n", __func__,
> +			img_request, img_request->offset, img_request->length);
> +	    	verbose = true;
> +	}
>  	for_each_obj_request_safe(img_request, obj_request, next_obj_request) {
>  		int ret;
> 
> +		if (verbose)
> +			printk("%s: obj_request %p (%llu/%llu)\n", __func__,
> +				obj_request, obj_request->offset,
> +				obj_request->length);
>  		ret = rbd_img_obj_request_submit(obj_request);
>  		if (ret)
>  			return ret;
> 
> 

Thanks ! I will check that tomorrow.

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

I think I've got it.  I'll explain, and we'll have to look at
the explanation more closely in the morning.

Bottom line is that I think the assertion is bogus.  Like
the other assertion that was not done under protection of
a lock, this one is being done in a way that's not safe.

First, here's a patch that I think might avoid the problem:

----------------------------------
Index: b/drivers/block/rbd.c
===================================================================
--- a/drivers/block/rbd.c
+++ b/drivers/block/rbd.c
@@ -2130,9 +2130,8 @@ static void rbd_img_obj_callback(struct
 	rbd_assert(which < img_request->obj_request_count);

 	spin_lock_irq(&img_request->completion_lock);
-	if (which > img_request->next_completion)
+	if (which != img_request->next_completion)
 		goto out;
-	rbd_assert(which == img_request->next_completion);

 	for_each_obj_request_from(img_request, obj_request) {
 		rbd_assert(more);
----------------------------------




Here's what I think is happening.  I'll annotate the function,
below.

First, we enter this function when an object request has
been marked "done."  In the case we're looking at, we
have an image request with two (or more) object requests.

static void rbd_img_obj_callback(struct rbd_obj_request *obj_request)
{
	struct rbd_img_request *img_request;
	u32 which = obj_request->which;
	bool more = true;

	rbd_assert(obj_request_img_data_test(obj_request));
	img_request = obj_request->img_request;

	dout("%s: img %p obj %p\n", __func__, img_request, obj_request);
	rbd_assert(img_request != NULL);
	rbd_assert(img_request->obj_request_count > 0);
	rbd_assert(which != BAD_WHICH);
	rbd_assert(which < img_request->obj_request_count);

Up to here, all is fine.  Well, *maybe*...  Anyway, I'll
work through that in the morning.  In any case, we are
examining fairly static fields in the object request.

	spin_lock_irq(&img_request->completion_lock);
	if (which > img_request->next_completion)
		goto out;

At this point we decide whether the object request now
completing is the next one.  If it's not, we're done;
whenever an earlier request (the first one) completes
it will ensure this one will get completed as well,
below.

But that's a problem.  In the loop below, the only condition
we're testing in order to account the completion of the
current *and subsequent* requests is whether each request
is marked "done."

What that means is that while the second request is waiting
to get the spinlock, the first one might be concurrently
going through the loop below.  It finds the second one "done"
and records that fact.  When it finishes the loop, it
updates the next_completion value and releases the lock.

The second request then enters the protected area, and
finds that its "which" value is *not* greater than the
next completion value.  It's in fact *less* than the
next_completion value, because the completion of this
second request has already been processed.

The problem got worse when we moved the spinlock (i.e.,
added protection around checking the next_completion
field) because now the second thread is actually waiting
before checking, so it's pretty much guaranteed it will
trigger the failure.

OK, back to bed.

					-Alex

	rbd_assert(which == img_request->next_completion);

	for_each_obj_request_from(img_request, obj_request) {
		rbd_assert(more);
		rbd_assert(which < img_request->obj_request_count);

		if (!obj_request_done_test(obj_request))
			break;
		more = rbd_img_obj_end_request(obj_request);
		which++;
	}

	rbd_assert(more ^ (which == img_request->obj_request_count));
	img_request->next_completion = which;
out:
	spin_unlock_irq(&img_request->completion_lock);

	if (!more)
		rbd_img_request_complete(img_request);
}

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

[Alex Elder]

On 03/26/2014 12:00 AM, Alex Elder wrote:
> I think I've got it.  I'll explain, and we'll have to look at
> the explanation more closely in the morning.
> 
> Bottom line is that I think the assertion is bogus.  Like
> the other assertion that was not done under protection of
> a lock, this one is being done in a way that's not safe.
> 
> First, here's a patch that I think might avoid the problem:
> 
> ----------------------------------
> Index: b/drivers/block/rbd.c
> ===================================================================
> --- a/drivers/block/rbd.c
> +++ b/drivers/block/rbd.c
> @@ -2130,9 +2130,8 @@ static void rbd_img_obj_callback(struct
>  	rbd_assert(which < img_request->obj_request_count);
> 
>  	spin_lock_irq(&img_request->completion_lock);
> -	if (which > img_request->next_completion)
> +	if (which != img_request->next_completion)
>  		goto out;
> -	rbd_assert(which == img_request->next_completion);
> 
>  	for_each_obj_request_from(img_request, obj_request) {
>  		rbd_assert(more);
> ----------------------------------


After some sleep (though not a lot), I remain convinced
the above will fix the problem, for now.  But it's not
quite enough.

The problem arises out of the fact that the thread of
control that marks an object request done is not necessarily
the thread of control that processing the completion of
that object (nor its associated image) request.  There are
no duplicate requests and no duplicate responses.


Object request completions are handled sequentially, based
on the range of address space involved in the requests.
This is the model required by the Linux blk_end_request()
interface.  Let's assume we have a single image request
that has two contiguous object requests, with the "lower"
object request involving bytes ending at the point the
"higher" one begins.

These object requests can be completed by their OSDs in
any order, and we will handle their completion in the
order their acknowledgement is received.  If we process
the higher request's acknowledgement first, that will
be the first to enter rbd_img_obj_callback().  Since
we will not have completed the lower one yet, nothing
more is done.

When the lower object request completes, it will enter
rbd_img_obj_callback() and find that it *is* the
next one we want completed.  So we'll enter a loop
that calls rbd_img_obj_end_request() on this request,
followed by its successor, doing completion processing
on any request that has by now been marked done.  In
the case I've described, the higher request will be
marked done, so it is here that its completion processing
is performed.

Once the last object request has been completed, we
call rbd_img_request_complete(), which will ultimately
lead to dropping a reference on the image request,
which leads to rbd_img_request_destroy().


What's happening in Olivier's case is that the
requests are actually completing *in order*, but
nearly simultaneously.  The lower and higher request
acknowledgements from their OSDs arrive, and their
consequent calls to rbd_img_obj_end_request() occur
at the same time.  The lower request wins the race
to get the spinlock before checking if it is the
next one to complete.  So the higher request waits;
but note that both of them have been marked "done"
at this point.

The lower request enters the completion loop, and
calls rbd_imb_obj_end_request() on both requests,
and updates the next_completion value before releasing
the spinlock.  Now the higher request acquires the
lock and gets its chance to check its position against
next_completion.  Since completion of this higher
request was now been done already while processing
the lower request, next_completion has now gone
past the higher request.  Therefore its "which"
value will not be higher than "next_completion"
but neither will it be equal to it, so the old
assertion would fail.

So my proposed fix just recognizes that, and allows
only the object request matching next_completion
to enter the completion loop, without assuming any
other request must have a greater "which" value.

Hopefully that's a more complete and clear
explanation of the problem.


Now, onto why that's not sufficient.

Basically, at the instant an image object request is
marked done, it is eligible to be completed by a
call to rbd_img_obj_end_request() by a concurrent
thread processing a lower-numbered object request in
the same image request.  And at just after that
instant (essentially, because of the protection
of the completion lock), the image request itself will
be completed by a call to rbd_img_request_complete().
It's likely this will drop the last reference to the
image request, so rbd_img_request_destroy() will be
called.  And that calls rbd_img_obj_request_del() on
each of its object requests.

In other words, conceivably the higher object
request that was stuck waiting for the spinlock
in rbd_img_obj_end_request() may now be getting
deleted from its image's request list.  (It
could be worse, it may have *just* finished
getting marked done and may not have even entered
rbd_img_obj_end_request() yet.)  And in the
process of getting deleted from its image request's
object request list, an object request gets
partially reinitialized, freed, and may get reused.


So...  in order to have a complete fix we need to
do some careful work with reference counting of
image requests and object requests, and avoid
having any of their content get disturbed until
the last reference is dropped.

Right now it's not quite right.  In particular, each
object request needs to have a *reference* to its
image request (not just a pointer to it), and it
should not be dropped until the the object request
gets destroyed.  And because one thread can destroy
an object request being actively used by another,
each object request should have reference that gets
held until it is no longer needed (probably at the
end of rbd_osd_req_callback()).


I think for the time being, the simple fix I
described last night will do, and it's somewhat
unlikely--though not impossible--for the problems
due to concurrent destruction will arise.  But
we do need a fix.  I'm prepared to create it, but
for now I'd like to have another opinion on my
treatise above.

					-Alex

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

[Ilya Dryomov]

On Wed, Mar 26, 2014 at 1:13 PM, Alex Elder <elder@ieee.org> wrote:
> On 03/26/2014 12:00 AM, Alex Elder wrote:
>> I think I've got it.  I'll explain, and we'll have to look at
>> the explanation more closely in the morning.
>>
>> Bottom line is that I think the assertion is bogus.  Like
>> the other assertion that was not done under protection of
>> a lock, this one is being done in a way that's not safe.
>>
>> First, here's a patch that I think might avoid the problem:
>>
>> ----------------------------------
>> Index: b/drivers/block/rbd.c
>> ===================================================================
>> --- a/drivers/block/rbd.c
>> +++ b/drivers/block/rbd.c
>> @@ -2130,9 +2130,8 @@ static void rbd_img_obj_callback(struct
>>       rbd_assert(which < img_request->obj_request_count);
>>
>>       spin_lock_irq(&img_request->completion_lock);
>> -     if (which > img_request->next_completion)
>> +     if (which != img_request->next_completion)
>>               goto out;
>> -     rbd_assert(which == img_request->next_completion);
>>
>>       for_each_obj_request_from(img_request, obj_request) {
>>               rbd_assert(more);
>> ----------------------------------
>
>
> After some sleep (though not a lot), I remain convinced
> the above will fix the problem, for now.  But it's not
> quite enough.
>
> The problem arises out of the fact that the thread of
> control that marks an object request done is not necessarily
> the thread of control that processing the completion of
> that object (nor its associated image) request.  There are
> no duplicate requests and no duplicate responses.
>
>
> Object request completions are handled sequentially, based
> on the range of address space involved in the requests.
> This is the model required by the Linux blk_end_request()
> interface.  Let's assume we have a single image request
> that has two contiguous object requests, with the "lower"
> object request involving bytes ending at the point the
> "higher" one begins.
>
> These object requests can be completed by their OSDs in
> any order, and we will handle their completion in the
> order their acknowledgement is received.  If we process
> the higher request's acknowledgement first, that will
> be the first to enter rbd_img_obj_callback().  Since
> we will not have completed the lower one yet, nothing
> more is done.
>
> When the lower object request completes, it will enter
> rbd_img_obj_callback() and find that it *is* the
> next one we want completed.  So we'll enter a loop
> that calls rbd_img_obj_end_request() on this request,
> followed by its successor, doing completion processing
> on any request that has by now been marked done.  In
> the case I've described, the higher request will be
> marked done, so it is here that its completion processing
> is performed.
>
> Once the last object request has been completed, we
> call rbd_img_request_complete(), which will ultimately
> lead to dropping a reference on the image request,
> which leads to rbd_img_request_destroy().
>
>
> What's happening in Olivier's case is that the
> requests are actually completing *in order*, but
> nearly simultaneously.  The lower and higher request
> acknowledgements from their OSDs arrive, and their
> consequent calls to rbd_img_obj_end_request() occur
> at the same time.  The lower request wins the race
> to get the spinlock before checking if it is the
> next one to complete.  So the higher request waits;
> but note that both of them have been marked "done"
> at this point.
>
> The lower request enters the completion loop, and
> calls rbd_imb_obj_end_request() on both requests,
> and updates the next_completion value before releasing
> the spinlock.  Now the higher request acquires the
> lock and gets its chance to check its position against
> next_completion.  Since completion of this higher
> request was now been done already while processing
> the lower request, next_completion has now gone
> past the higher request.  Therefore its "which"
> value will not be higher than "next_completion"
> but neither will it be equal to it, so the old
> assertion would fail.
>
> So my proposed fix just recognizes that, and allows
> only the object request matching next_completion
> to enter the completion loop, without assuming any
> other request must have a greater "which" value.
>
> Hopefully that's a more complete and clear
> explanation of the problem.
>
>
> Now, onto why that's not sufficient.
>
> Basically, at the instant an image object request is
> marked done, it is eligible to be completed by a
> call to rbd_img_obj_end_request() by a concurrent
> thread processing a lower-numbered object request in
> the same image request.  And at just after that
> instant (essentially, because of the protection
> of the completion lock), the image request itself will
> be completed by a call to rbd_img_request_complete().
> It's likely this will drop the last reference to the
> image request, so rbd_img_request_destroy() will be
> called.  And that calls rbd_img_obj_request_del() on
> each of its object requests.
>
> In other words, conceivably the higher object
> request that was stuck waiting for the spinlock
> in rbd_img_obj_end_request() may now be getting
> deleted from its image's request list.  (It
> could be worse, it may have *just* finished
> getting marked done and may not have even entered
> rbd_img_obj_end_request() yet.)  And in the
> process of getting deleted from its image request's
> object request list, an object request gets
> partially reinitialized, freed, and may get reused.
>
>
> So...  in order to have a complete fix we need to
> do some careful work with reference counting of
> image requests and object requests, and avoid
> having any of their content get disturbed until
> the last reference is dropped.
>
> Right now it's not quite right.  In particular, each
> object request needs to have a *reference* to its
> image request (not just a pointer to it), and it
> should not be dropped until the the object request
> gets destroyed.  And because one thread can destroy
> an object request being actively used by another,
> each object request should have reference that gets
> held until it is no longer needed (probably at the
> end of rbd_osd_req_callback()).
>
>
> I think for the time being, the simple fix I
> described last night will do, and it's somewhat
> unlikely--though not impossible--for the problems
> due to concurrent destruction will arise.  But
> we do need a fix.  I'm prepared to create it, but
> for now I'd like to have another opinion on my
> treatise above.

This all makes sense, I think reference counting is the right thing to
do.  We definitely do need a real fix, with the simple fix we still
have a potential use-after-free on img_request itself, not to mention
obj_requests.

It looks like img_request kref currenlty exists for posterity only.
Unless I'm missing something, its counter is set to 1 in
rbd_img_request_create() and is not incremented anywhere else, which
means that the instant rbd_img_request_put() is called, img_request is
freed.  I naively assumed it was incremented and decremented in
rbd_img_obj_request_add() and rbd_img_obj_request_del() respectively..
Maybe that's something we should look at first?

Thanks,

                Ilya

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

[Alex Elder]

On 03/26/2014 06:43 AM, Ilya Dryomov wrote:
> It looks like img_request kref currenlty exists for posterity only.
> Unless I'm missing something, its counter is set to 1 in
> rbd_img_request_create() and is not incremented anywhere else, which
> means that the instant rbd_img_request_put() is called, img_request is
> freed.  I naively assumed it was incremented and decremented in
> rbd_img_obj_request_add() and rbd_img_obj_request_del() respectively..
> Maybe that's something we should look at first?

I believe it was something that I never finished implementing.

So yes, the kref is there to be used, it just isn't, really.

If you want to give it a try, be my guest.  I'll review it
carefully.  (I can't really test my changes very well anyway.)

If you want me to do it, let me know.

					-Alex

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

[Ilya Dryomov]

On Wed, Mar 26, 2014 at 1:47 PM, Alex Elder <elder@ieee.org> wrote:
> On 03/26/2014 06:43 AM, Ilya Dryomov wrote:
>> It looks like img_request kref currenlty exists for posterity only.
>> Unless I'm missing something, its counter is set to 1 in
>> rbd_img_request_create() and is not incremented anywhere else, which
>> means that the instant rbd_img_request_put() is called, img_request is
>> freed.  I naively assumed it was incremented and decremented in
>> rbd_img_obj_request_add() and rbd_img_obj_request_del() respectively..
>> Maybe that's something we should look at first?
>
> I believe it was something that I never finished implementing.
>
> So yes, the kref is there to be used, it just isn't, really.
>
> If you want to give it a try, be my guest.  I'll review it
> carefully.  (I can't really test my changes very well anyway.)
>
> If you want me to do it, let me know.

I think you should do it ;)  If time is not a big issue, that is.  You
have a much more complete picture in your head.

Thanks,

                Ilya

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

[Alex Elder]

Olivier reports that with the simple patch I provided
(which changed a "<" to a "!=" and removed an assertion)
he is running successfully.

To me this is fantastic news, and you can see I posted
a patch with the fix.

There remains a race condition though, one which I described
in a separate message earlier today.  I don't think it will
prove to be a problem in practice, but I agreed to work on
a fix to ensure the race condition is eliminated.  It will
require some work with reference counting image and object
requests.

The fix won't be coming today.  But I aim to provide it
in a matter of several days.

					-Alex

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

[Olivier Bonvalet]

Le mercredi 26 mars 2014 à 15:58 -0500, Alex Elder a écrit :
> Olivier reports that with the simple patch I provided
> (which changed a "<" to a "!=" and removed an assertion)
> he is running successfully.
> 
> To me this is fantastic news, and you can see I posted
> a patch with the fix.
> 
> There remains a race condition though, one which I described
> in a separate message earlier today.  I don't think it will
> prove to be a problem in practice, but I agreed to work on
> a fix to ensure the race condition is eliminated.  It will
> require some work with reference counting image and object
> requests.
> 
> The fix won't be coming today.  But I aim to provide it
> in a matter of several days.
> 
> 					-Alex
> 

One question from one of my customers : why am I the only one to
complain about that problem ? 
I know that Ceph users often use qemu/librbd instead of kernel client,
but what is the trigger of those «race condition» ? Having "multiple
requests" per RBD image ? It should be a normal use, no ?

If someone can help me give an explanation, thanks :)

Olivier

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Ilya Dryomov]

On Thu, Mar 27, 2014 at 9:48 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> Le mercredi 26 mars 2014 à 15:58 -0500, Alex Elder a écrit :
>> Olivier reports that with the simple patch I provided
>> (which changed a "<" to a "!=" and removed an assertion)
>> he is running successfully.
>>
>> To me this is fantastic news, and you can see I posted
>> a patch with the fix.
>>
>> There remains a race condition though, one which I described
>> in a separate message earlier today.  I don't think it will
>> prove to be a problem in practice, but I agreed to work on
>> a fix to ensure the race condition is eliminated.  It will
>> require some work with reference counting image and object
>> requests.
>>
>> The fix won't be coming today.  But I aim to provide it
>> in a matter of several days.
>>
>>                                       -Alex
>>
>
> One question from one of my customers : why am I the only one to
> complain about that problem ?
> I know that Ceph users often use qemu/librbd instead of kernel client,
> but what is the trigger of those «race condition» ? Having "multiple
> requests" per RBD image ? It should be a normal use, no ?
>
> If someone can help me give an explanation, thanks :)

We've had a couple more, similar reports in the last few months.
However you are the first reporter who was able to trigger this race
often enough to track it down.  This race condition (read: bug) is
kernel client specific, qemu/librbd is unaffected.  Having an rbd
request that spans multiple RADOS objects and therefore results in
multiple object requests is normal use, it's just that particular piece
of code turned out to be prone to a subtle race.  You have to keep in
mind that races are all about timing and relative order of events, so
simply issuing a multi-object rbd request is not enough to trigger it,
stars have to align too ;)

Thanks,

                Ilya
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le jeudi 27 mars 2014 à 10:45 +0200, Ilya Dryomov a écrit :
> On Thu, Mar 27, 2014 at 9:48 AM, Olivier Bonvalet <ceph.list@daevel.fr> wrote:
> > Le mercredi 26 mars 2014 à 15:58 -0500, Alex Elder a écrit :
> >> Olivier reports that with the simple patch I provided
> >> (which changed a "<" to a "!=" and removed an assertion)
> >> he is running successfully.
> >>
> >> To me this is fantastic news, and you can see I posted
> >> a patch with the fix.
> >>
> >> There remains a race condition though, one which I described
> >> in a separate message earlier today.  I don't think it will
> >> prove to be a problem in practice, but I agreed to work on
> >> a fix to ensure the race condition is eliminated.  It will
> >> require some work with reference counting image and object
> >> requests.
> >>
> >> The fix won't be coming today.  But I aim to provide it
> >> in a matter of several days.
> >>
> >>                                       -Alex
> >>
> >
> > One question from one of my customers : why am I the only one to
> > complain about that problem ?
> > I know that Ceph users often use qemu/librbd instead of kernel client,
> > but what is the trigger of those «race condition» ? Having "multiple
> > requests" per RBD image ? It should be a normal use, no ?
> >
> > If someone can help me give an explanation, thanks :)
> 
> We've had a couple more, similar reports in the last few months.
> However you are the first reporter who was able to trigger this race
> often enough to track it down.  This race condition (read: bug) is
> kernel client specific, qemu/librbd is unaffected.  Having an rbd
> request that spans multiple RADOS objects and therefore results in
> multiple object requests is normal use, it's just that particular piece
> of code turned out to be prone to a subtle race.  You have to keep in
> mind that races are all about timing and relative order of events, so
> simply issuing a multi-object rbd request is not enough to trigger it,
> stars have to align too ;)
> 
> Thanks,
> 
>                 Ilya
> 

Great, thanks !

Olivier

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mercredi 26 mars 2014 à 02:50 +0100, Olivier Bonvalet a écrit :
> Le mercredi 26 mars 2014 à 02:33 +0100, Olivier Bonvalet a écrit :
> > Thanks for your patch.
> > 
> > This is an output of a crash case :
> > 
> > Mar 26 02:31:18 alg kernel: [  965.366895] rbd_img_obj_callback: bad image object request information:
> > Mar 26 02:31:18 alg kernel: [  965.366905] obj_request ffff880224bc9528
> > Mar 26 02:31:18 alg kernel: [  965.366909]     ->object_name <(null)>
> > Mar 26 02:31:18 alg kernel: [  965.366913]     ->offset 0
> > Mar 26 02:31:18 alg kernel: [  965.366917]     ->length 4096
> > Mar 26 02:31:18 alg kernel: [  965.366921]     ->type 0x1
> > Mar 26 02:31:18 alg kernel: [  965.366925]     ->flags 0x3
> > Mar 26 02:31:18 alg kernel: [  965.366929]     ->img_request           (null)
> > Mar 26 02:31:18 alg kernel: [  965.366933]     ->which 4294967295
> > Mar 26 02:31:18 alg kernel: [  965.366936]     ->xferred 4096
> > Mar 26 02:31:18 alg kernel: [  965.366940]     ->result 0
> > Mar 26 02:31:18 alg kernel: [  965.366943]     ->kref 0
> > Mar 26 02:31:18 alg kernel: [  965.366947] img_request ffff880222f4fb50
> > Mar 26 02:31:18 alg kernel: [  965.366950]     ->snap 0xfffffffffffffffe
> > Mar 26 02:31:18 alg kernel: [  965.366954]     ->offset 1417662464
> > Mar 26 02:31:18 alg kernel: [  965.366957]     ->length 16384
> > Mar 26 02:31:18 alg kernel: [  965.366960]     ->flags 0x0
> > Mar 26 02:31:18 alg kernel: [  965.366963]     ->obj_request_count 0
> > Mar 26 02:31:18 alg kernel: [  965.366966]     ->next_completion 2
> > Mar 26 02:31:18 alg kernel: [  965.366969]     ->xferred 16384
> > Mar 26 02:31:18 alg kernel: [  965.366973]     ->result 0
> > Mar 26 02:31:18 alg kernel: [  965.366976]     ->obj_requests head ffff880222f4fbb0
> > Mar 26 02:31:18 alg kernel: [  965.366980]     ->kref 0
> > Mar 26 02:31:18 alg kernel: [  965.366985] 
> > Mar 26 02:31:18 alg kernel: [  965.366985] Assertion failure in rbd_img_obj_callback() at line 2165:
> > Mar 26 02:31:18 alg kernel: [  965.366985] 
> > Mar 26 02:31:18 alg kernel: [  965.366985] 	rbd_assert(which == img_request->next_completion);
> > Mar 26 02:31:18 alg kernel: [  965.366985] 
> > Mar 26 02:31:18 alg kernel: [  965.367185] ------------[ cut here ]------------
> > Mar 26 02:31:18 alg kernel: [  965.367241] kernel BUG at drivers/block/rbd.c:2165!
> > 
> > 
> > I hope it can help.
> > 
> > 
> > --
> 
> and a second one, very similar :
> 
> Mar 26 02:48:27 alg kernel: [  681.167833] rbd_img_obj_callback: bad image object request information:
> Mar 26 02:48:27 alg kernel: [  681.167836] obj_request ffff88022e1e2828
> Mar 26 02:48:27 alg kernel: [  681.167837]     ->object_name <(null)>
> Mar 26 02:48:27 alg kernel: [  681.167838]     ->offset 0
> Mar 26 02:48:27 alg kernel: [  681.167839]     ->length 4096
> Mar 26 02:48:27 alg kernel: [  681.167840]     ->type 0x1
> Mar 26 02:48:27 alg kernel: [  681.167840]     ->flags 0x3
> Mar 26 02:48:27 alg kernel: [  681.167841]     ->img_request           (null)
> Mar 26 02:48:27 alg kernel: [  681.167842]     ->which 4294967295
> Mar 26 02:48:27 alg kernel: [  681.167843]     ->xferred 4096
> Mar 26 02:48:27 alg kernel: [  681.167844]     ->result 0
> Mar 26 02:48:27 alg kernel: [  681.167844]     ->kref 0
> Mar 26 02:48:27 alg kernel: [  681.167845] img_request ffff88021f555f10
> Mar 26 02:48:27 alg kernel: [  681.167846]     ->snap 0xfffffffffffffffe
> Mar 26 02:48:27 alg kernel: [  681.167847]     ->offset 28072464384
> Mar 26 02:48:27 alg kernel: [  681.167847]     ->length 16384
> Mar 26 02:48:27 alg kernel: [  681.167848]     ->flags 0x0
> Mar 26 02:48:27 alg kernel: [  681.167849]     ->obj_request_count 0
> Mar 26 02:48:27 alg kernel: [  681.167850]     ->next_completion 2
> Mar 26 02:48:27 alg kernel: [  681.167850]     ->xferred 16384
> Mar 26 02:48:27 alg kernel: [  681.167851]     ->result 0
> Mar 26 02:48:27 alg kernel: [  681.167852]     ->obj_requests head ffff88021f555f70
> Mar 26 02:48:27 alg kernel: [  681.167853]     ->kref 0
> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.167854] Assertion failure in rbd_img_obj_callback() at line 2165:
> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.167854] 	rbd_assert(which == img_request->next_completion);
> Mar 26 02:48:27 alg kernel: [  681.167854] 
> Mar 26 02:48:27 alg kernel: [  681.168117] ------------[ cut here ]------------
> Mar 26 02:48:27 alg kernel: [  681.168211] kernel BUG at drivers/block/rbd.c:2165!
> 
> 
> --

And a last one. As you said, it looks like to be same problem, each
time :

Mar 26 03:32:53 murmillia kernel: [  533.506391] rbd_img_obj_callback: bad image object request information:
Mar 26 03:32:53 murmillia kernel: [  533.506395] obj_request ffff88024fe73da8
Mar 26 03:32:53 murmillia kernel: [  533.506396]     ->object_name <(null)>
Mar 26 03:32:53 murmillia kernel: [  533.506397]     ->offset 0
Mar 26 03:32:53 murmillia kernel: [  533.506398]     ->length 24576
Mar 26 03:32:53 murmillia kernel: [  533.506399]     ->type 0x1
Mar 26 03:32:53 murmillia kernel: [  533.506400]     ->flags 0x3
Mar 26 03:32:53 murmillia kernel: [  533.506400]     ->img_request           (null)
Mar 26 03:32:53 murmillia kernel: [  533.506401]     ->which 4294967295
Mar 26 03:32:53 murmillia kernel: [  533.506402]     ->xferred 24576
Mar 26 03:32:53 murmillia kernel: [  533.506403]     ->result 0
Mar 26 03:32:53 murmillia kernel: [  533.506404]     ->kref 0
Mar 26 03:32:53 murmillia kernel: [  533.506405] img_request ffff880256f0cad8
Mar 26 03:32:53 murmillia kernel: [  533.506405]     ->snap 0xfffffffffffffffe
Mar 26 03:32:53 murmillia kernel: [  533.506406]     ->offset 67637329920
Mar 26 03:32:53 murmillia kernel: [  533.506407]     ->length 40960
Mar 26 03:32:53 murmillia kernel: [  533.506408]     ->flags 0x0
Mar 26 03:32:53 murmillia kernel: [  533.506409]     ->obj_request_count 0
Mar 26 03:32:53 murmillia kernel: [  533.506410]     ->next_completion 2
Mar 26 03:32:53 murmillia kernel: [  533.506410]     ->xferred 40960
Mar 26 03:32:53 murmillia kernel: [  533.506411]     ->result 0
Mar 26 03:32:53 murmillia kernel: [  533.506412]     ->obj_requests head ffff880256f0cb38
Mar 26 03:32:53 murmillia kernel: [  533.506413]     ->kref 0
Mar 26 03:32:53 murmillia kernel: [  533.506414] 
Mar 26 03:32:53 murmillia kernel: [  533.506414] Assertion failure in rbd_img_obj_callback() at line 2165:
Mar 26 03:32:53 murmillia kernel: [  533.506414] 
Mar 26 03:32:53 murmillia kernel: [  533.506414] 	rbd_assert(which == img_request->next_completion);
Mar 26 03:32:53 murmillia kernel: [  533.506414] 
Mar 26 03:32:53 murmillia kernel: [  533.506620] ------------[ cut here ]------------


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

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

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 21:54 -0500, Alex Elder a écrit :
> 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
> 

I'm pretty sure that the new high frequency of the crash is a part of
the problem. Before the spinlock fix, the problem was hard to trigger
(once per week, maybe per day on two hosts only). Now it's really hard
to *don't* trigger it : I now have 5 client servers, and only one of
them have more than one hour of uptime.

I can be wrong, since I don't know neither really understand the code,
but from what I understand, there was a "ghost" request, a duplicate,
that follow the good one. Before the spinlock fix, this second request
could be proceed if next_completion was not yet modified, so this "bug"
hadn't a big impact.

But now that next_completion is properly checked with the spinlock, that
ghost request is no more proceed neither ignored, it throws a kernel
bug.

From my point of view, since it seems to be an orphaned read request, it
should be track in logs (this request should not exists) but then it
should be ignored without locking the kernel.

From now, I switch on previous kernels (yes, I should do that some hours
sooner ;)).

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
> Hi,
> 
> what can/should I do to help fix that problem ?
> 
> for now, RBD kernel client hang on : 
>         Assertion failure in rbd_img_obj_callback() at line 2131:
>            rbd_assert(which >= img_request->next_completion);
> 
> or on :
>         Assertion failure in rbd_img_obj_callback() at line 2127:
>             rbd_assert(img_request != NULL);
> 
> 
> I have both case at least once per week, on latest 3.13.5 kernels.
> 
> It seems that the problem occurs only on more loaded servers (I have 4
> near same servers, and crash occurs on two of them. If I move the VM,
> crash follows...).
> 
> Olivier
> 
> --

Hi,

so. After some days without any problems, RBD crashed toonight :

Apr  5 02:52:24 rurkh kernel: [799426.461742] 
Apr  5 02:52:24 rurkh kernel: [799426.461742] Assertion failure in rbd_img_obj_callback() at line 2128:
Apr  5 02:52:24 rurkh kernel: [799426.461742] 
Apr  5 02:52:24 rurkh kernel: [799426.461742]   rbd_assert(img_request->obj_request_count > 0);
Apr  5 02:52:24 rurkh kernel: [799426.461742] 
Apr  5 02:52:24 rurkh kernel: [799426.461958] ------------[ cut here ]------------
Apr  5 02:52:24 rurkh kernel: [799426.461997] kernel BUG at drivers/block/rbd.c:2128!
Apr  5 02:52:24 rurkh kernel: [799426.462036] invalid opcode: 0000 [#1] SMP 
Apr  5 02:52:24 rurkh kernel: [799426.462080] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs
 libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core evdev i2c_i801 lpc_ich mfd_core ioatdma shpchp ipmi
_si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common isci ahci ehci_pci libsas libahci mega
raid_sas ehci_hcd libata scsi_transport_sas igb usbcore scsi_mod i2c_algo_bit ixgbe i2c_core usb_common dca ptp pps_core mdio
Apr  5 02:52:24 rurkh kernel: [799426.462579] CPU: 0 PID: 15975 Comm: kworker/0:0 Not tainted 3.13-dae-dom0 #24
Apr  5 02:52:24 rurkh kernel: [799426.462644] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
Apr  5 02:52:24 rurkh kernel: [799426.462717] Workqueue: ceph-msgr con_work [libceph]
Apr  5 02:52:24 rurkh kernel: [799426.462759] task: ffff88024cd9a8a0 ti: ffff88021a4e4000 task.ti: ffff88021a4e4000
Apr  5 02:52:24 rurkh kernel: [799426.462825] RIP: e030:[<ffffffffa0305ae8>]  [<ffffffffa0305ae8>] rbd_img_obj_callback+0x91/0x3a2 [rbd]
Apr  5 02:52:24 rurkh kernel: [799426.462901] RSP: e02b:ffff88021a4e5ce8  EFLAGS: 00010282
Apr  5 02:52:24 rurkh kernel: [799426.462940] RAX: 000000000000006d RBX: ffff88023f8f6ec8 RCX: 0000000000000000
Apr  5 02:52:24 rurkh kernel: [799426.463005] RDX: ffff88027fe0eb50 RSI: ffff88027fe0e1a8 RDI: ffff88021a4e02a8
Apr  5 02:52:24 rurkh kernel: [799426.463069] RBP: ffff88021c90a718 R08: 0000000000000000 R09: 0000000000000000
Apr  5 02:52:24 rurkh kernel: [799426.463134] R10: 0000000000000000 R11: 000000000000084e R12: 0000000000000001
Apr  5 02:52:24 rurkh kernel: [799426.463197] R13: 0000000000000000 R14: ffff88025584a130 R15: 0000000000000000
Apr  5 02:52:24 rurkh kernel: [799426.481060] FS:  00007f1c6138f720(0000) GS:ffff88027fe00000(0000) knlGS:0000000000000000
Apr  5 02:52:24 rurkh kernel: [799426.481130] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
Apr  5 02:52:24 rurkh kernel: [799426.481170] CR2: 00007f1c6139f000 CR3: 000000023825c000 CR4: 0000000000042660
Apr  5 02:52:24 rurkh kernel: [799426.481235] Stack:
Apr  5 02:52:24 rurkh kernel: [799426.481266]  000000000000000d ffff880254da107d ffffffffffffffff ffff880254da1048
Apr  5 02:52:24 rurkh kernel: [799426.481349]  ffff88025584a128 ffff88026dc59718 0000000000000000 ffff88025584a130
Apr  5 02:52:24 rurkh kernel: [799426.481429]  0000000000000000 ffffffffa02e4595 0000000000000015 ffff88026dc59770
Apr  5 02:52:24 rurkh kernel: [799426.481510] Call Trace:
Apr  5 02:52:24 rurkh kernel: [799426.481554]  [<ffffffffa02e4595>] ? dispatch+0x3e4/0x55e [libceph]
Apr  5 02:52:24 rurkh kernel: [799426.481600]  [<ffffffffa02df0fc>] ? con_work+0xf6e/0x1a65 [libceph]
Apr  5 02:52:24 rurkh kernel: [799426.481646]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
Apr  5 02:52:24 rurkh kernel: [799426.481687]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
Apr  5 02:52:24 rurkh kernel: [799426.481732]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
Apr  5 02:52:24 rurkh kernel: [799426.481775]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
Apr  5 02:52:24 rurkh kernel: [799426.481817]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
Apr  5 02:52:24 rurkh kernel: [799426.481859]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
Apr  5 02:52:24 rurkh kernel: [799426.481900]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Apr  5 02:52:24 rurkh kernel: [799426.481944]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
Apr  5 02:52:24 rurkh kernel: [799426.481985]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
Apr  5 02:52:24 rurkh kernel: [799426.482025] Code: 26 06 e1 0f 0b 8b 45 5c 85 c0 75 21 48 c7 c1 66 88 30 a0 ba 50 08 00 00 48 c7 c6 50 99 30 a0 48 c7 c7 1f 81 30 a0 e8 5b 26 06 e1 <0f> 0b 41 83 fc ff 75 23 48 c7 c1 f4 8b 30 a0 ba 51 08 00 00 31 
Apr  5 02:52:24 rurkh kernel: [799426.482413] RIP  [<ffffffffa0305ae8>] rbd_img_obj_callback+0x91/0x3a2 [rbd]
Apr  5 02:52:24 rurkh kernel: [799426.482462]  RSP <ffff88021a4e5ce8>
Apr  5 02:52:24 rurkh kernel: [799426.483907] ---[ end trace 4aea8b8c107c24be ]---


At this time there was a lot of IO, because of backups in VM.
(but no RBD snapshot create or remove)


--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 04/04/2014 08:16 PM, Olivier Bonvalet wrote:
> Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
>> Hi,
>>
>> what can/should I do to help fix that problem ?
>>
>> for now, RBD kernel client hang on : 
>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>            rbd_assert(which >= img_request->next_completion);
>>
>> or on :
>>         Assertion failure in rbd_img_obj_callback() at line 2127:
>>             rbd_assert(img_request != NULL);
>>
>>
>> I have both case at least once per week, on latest 3.13.5 kernels.
>>
>> It seems that the problem occurs only on more loaded servers (I have 4
>> near same servers, and crash occurs on two of them. If I move the VM,
>> crash follows...).
>>
>> Olivier
>>
>> --
> 
> Hi,
> 
> so. After some days without any problems, RBD crashed toonight :

Unfortunately this could be a symptom of the same sort of race.
When a object request is removed from its image request's list
the request count gets decremented.  To be honest, all of these
assertions in rbd_img_obj_callback() are probably unsafe, at
least until I get the patch that does proper reference counting
implemented:

        rbd_assert(img_request != NULL);
        rbd_assert(img_request->obj_request_count > 0);
        rbd_assert(which != BAD_WHICH);
        rbd_assert(which < img_request->obj_request_count);

Until then I think you can avoid this by commenting out those
assertions.  I'm afraid there will remain a (smaller) window
of opportunity for a problem to occur, but I believe commenting
those out will help for now.

I'm very sorry you're hitting these.  I'll see if I can get
a comprehensive fix this weekend.

					-Alex



> Apr  5 02:52:24 rurkh kernel: [799426.461742] 
> Apr  5 02:52:24 rurkh kernel: [799426.461742] Assertion failure in rbd_img_obj_callback() at line 2128:
> Apr  5 02:52:24 rurkh kernel: [799426.461742] 
> Apr  5 02:52:24 rurkh kernel: [799426.461742]   rbd_assert(img_request->obj_request_count > 0);
> Apr  5 02:52:24 rurkh kernel: [799426.461742] 
> Apr  5 02:52:24 rurkh kernel: [799426.461958] ------------[ cut here ]------------
> Apr  5 02:52:24 rurkh kernel: [799426.461997] kernel BUG at drivers/block/rbd.c:2128!
> Apr  5 02:52:24 rurkh kernel: [799426.462036] invalid opcode: 0000 [#1] SMP 
> Apr  5 02:52:24 rurkh kernel: [799426.462080] Modules linked in: cbc rbd libceph xen_gntdev xt_physdev iptable_filter ip_tables x_tables xfs
>  libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core evdev i2c_i801 lpc_ich mfd_core ioatdma shpchp ipmi
> _si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common isci ahci ehci_pci libsas libahci mega
> raid_sas ehci_hcd libata scsi_transport_sas igb usbcore scsi_mod i2c_algo_bit ixgbe i2c_core usb_common dca ptp pps_core mdio
> Apr  5 02:52:24 rurkh kernel: [799426.462579] CPU: 0 PID: 15975 Comm: kworker/0:0 Not tainted 3.13-dae-dom0 #24
> Apr  5 02:52:24 rurkh kernel: [799426.462644] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 3.0 07/24/2013
> Apr  5 02:52:24 rurkh kernel: [799426.462717] Workqueue: ceph-msgr con_work [libceph]
> Apr  5 02:52:24 rurkh kernel: [799426.462759] task: ffff88024cd9a8a0 ti: ffff88021a4e4000 task.ti: ffff88021a4e4000
> Apr  5 02:52:24 rurkh kernel: [799426.462825] RIP: e030:[<ffffffffa0305ae8>]  [<ffffffffa0305ae8>] rbd_img_obj_callback+0x91/0x3a2 [rbd]
> Apr  5 02:52:24 rurkh kernel: [799426.462901] RSP: e02b:ffff88021a4e5ce8  EFLAGS: 00010282
> Apr  5 02:52:24 rurkh kernel: [799426.462940] RAX: 000000000000006d RBX: ffff88023f8f6ec8 RCX: 0000000000000000
> Apr  5 02:52:24 rurkh kernel: [799426.463005] RDX: ffff88027fe0eb50 RSI: ffff88027fe0e1a8 RDI: ffff88021a4e02a8
> Apr  5 02:52:24 rurkh kernel: [799426.463069] RBP: ffff88021c90a718 R08: 0000000000000000 R09: 0000000000000000
> Apr  5 02:52:24 rurkh kernel: [799426.463134] R10: 0000000000000000 R11: 000000000000084e R12: 0000000000000001
> Apr  5 02:52:24 rurkh kernel: [799426.463197] R13: 0000000000000000 R14: ffff88025584a130 R15: 0000000000000000
> Apr  5 02:52:24 rurkh kernel: [799426.481060] FS:  00007f1c6138f720(0000) GS:ffff88027fe00000(0000) knlGS:0000000000000000
> Apr  5 02:52:24 rurkh kernel: [799426.481130] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
> Apr  5 02:52:24 rurkh kernel: [799426.481170] CR2: 00007f1c6139f000 CR3: 000000023825c000 CR4: 0000000000042660
> Apr  5 02:52:24 rurkh kernel: [799426.481235] Stack:
> Apr  5 02:52:24 rurkh kernel: [799426.481266]  000000000000000d ffff880254da107d ffffffffffffffff ffff880254da1048
> Apr  5 02:52:24 rurkh kernel: [799426.481349]  ffff88025584a128 ffff88026dc59718 0000000000000000 ffff88025584a130
> Apr  5 02:52:24 rurkh kernel: [799426.481429]  0000000000000000 ffffffffa02e4595 0000000000000015 ffff88026dc59770
> Apr  5 02:52:24 rurkh kernel: [799426.481510] Call Trace:
> Apr  5 02:52:24 rurkh kernel: [799426.481554]  [<ffffffffa02e4595>] ? dispatch+0x3e4/0x55e [libceph]
> Apr  5 02:52:24 rurkh kernel: [799426.481600]  [<ffffffffa02df0fc>] ? con_work+0xf6e/0x1a65 [libceph]
> Apr  5 02:52:24 rurkh kernel: [799426.481646]  [<ffffffff81051f83>] ? mmdrop+0xd/0x1c
> Apr  5 02:52:24 rurkh kernel: [799426.481687]  [<ffffffff8105265e>] ? finish_task_switch+0x4d/0x83
> Apr  5 02:52:24 rurkh kernel: [799426.481732]  [<ffffffff810484d7>] ? process_one_work+0x15a/0x214
> Apr  5 02:52:24 rurkh kernel: [799426.481775]  [<ffffffff8104895b>] ? worker_thread+0x139/0x1de
> Apr  5 02:52:24 rurkh kernel: [799426.481817]  [<ffffffff81048822>] ? rescuer_thread+0x26e/0x26e
> Apr  5 02:52:24 rurkh kernel: [799426.481859]  [<ffffffff8104cff6>] ? kthread+0x9e/0xa6
> Apr  5 02:52:24 rurkh kernel: [799426.481900]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Apr  5 02:52:24 rurkh kernel: [799426.481944]  [<ffffffff8137260c>] ? ret_from_fork+0x7c/0xb0
> Apr  5 02:52:24 rurkh kernel: [799426.481985]  [<ffffffff8104cf58>] ? __kthread_parkme+0x55/0x55
> Apr  5 02:52:24 rurkh kernel: [799426.482025] Code: 26 06 e1 0f 0b 8b 45 5c 85 c0 75 21 48 c7 c1 66 88 30 a0 ba 50 08 00 00 48 c7 c6 50 99 30 a0 48 c7 c7 1f 81 30 a0 e8 5b 26 06 e1 <0f> 0b 41 83 fc ff 75 23 48 c7 c1 f4 8b 30 a0 ba 51 08 00 00 31 
> Apr  5 02:52:24 rurkh kernel: [799426.482413] RIP  [<ffffffffa0305ae8>] rbd_img_obj_callback+0x91/0x3a2 [rbd]
> Apr  5 02:52:24 rurkh kernel: [799426.482462]  RSP <ffff88021a4e5ce8>
> Apr  5 02:52:24 rurkh kernel: [799426.483907] ---[ end trace 4aea8b8c107c24be ]---
> 
> 
> At this time there was a lot of IO, because of backups in VM.
> (but no RBD snapshot create or remove)
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le vendredi 04 avril 2014 à 20:57 -0500, Alex Elder a écrit :
> On 04/04/2014 08:16 PM, Olivier Bonvalet wrote:
> > Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
> >> Hi,
> >>
> >> what can/should I do to help fix that problem ?
> >>
> >> for now, RBD kernel client hang on : 
> >>         Assertion failure in rbd_img_obj_callback() at line 2131:
> >>            rbd_assert(which >= img_request->next_completion);
> >>
> >> or on :
> >>         Assertion failure in rbd_img_obj_callback() at line 2127:
> >>             rbd_assert(img_request != NULL);
> >>
> >>
> >> I have both case at least once per week, on latest 3.13.5 kernels.
> >>
> >> It seems that the problem occurs only on more loaded servers (I have 4
> >> near same servers, and crash occurs on two of them. If I move the VM,
> >> crash follows...).
> >>
> >> Olivier
> >>
> >> --
> > 
> > Hi,
> > 
> > so. After some days without any problems, RBD crashed toonight :
> 
> Unfortunately this could be a symptom of the same sort of race.
> When a object request is removed from its image request's list
> the request count gets decremented.  To be honest, all of these
> assertions in rbd_img_obj_callback() are probably unsafe, at
> least until I get the patch that does proper reference counting
> implemented:
> 
>         rbd_assert(img_request != NULL);
>         rbd_assert(img_request->obj_request_count > 0);
>         rbd_assert(which != BAD_WHICH);
>         rbd_assert(which < img_request->obj_request_count);
> 
> Until then I think you can avoid this by commenting out those
> assertions.  I'm afraid there will remain a (smaller) window
> of opportunity for a problem to occur, but I believe commenting
> those out will help for now.
> 
> I'm very sorry you're hitting these.  I'll see if I can get
> a comprehensive fix this weekend.
> 
> 					-Alex

Thanks for your help, really.

By removing those asserts, can I throw any data corruption ?

Olivier

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 04/05/2014 03:09 AM, Olivier Bonvalet wrote:
> Le vendredi 04 avril 2014 à 20:57 -0500, Alex Elder a écrit :
>> On 04/04/2014 08:16 PM, Olivier Bonvalet wrote:
>>> Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
>>>> Hi,
>>>>
>>>> what can/should I do to help fix that problem ?
>>>>
>>>> for now, RBD kernel client hang on : 
>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>>            rbd_assert(which >= img_request->next_completion);
>>>>
>>>> or on :
>>>>         Assertion failure in rbd_img_obj_callback() at line 2127:
>>>>             rbd_assert(img_request != NULL);
>>>>
>>>>
>>>> I have both case at least once per week, on latest 3.13.5 kernels.
>>>>
>>>> It seems that the problem occurs only on more loaded servers (I have 4
>>>> near same servers, and crash occurs on two of them. If I move the VM,
>>>> crash follows...).
>>>>
>>>> Olivier
>>>>
>>>> --
>>>
>>> Hi,
>>>
>>> so. After some days without any problems, RBD crashed toonight :
>>
>> Unfortunately this could be a symptom of the same sort of race.
>> When a object request is removed from its image request's list
>> the request count gets decremented.  To be honest, all of these
>> assertions in rbd_img_obj_callback() are probably unsafe, at
>> least until I get the patch that does proper reference counting
>> implemented:
>>
>>         rbd_assert(img_request != NULL);
>>         rbd_assert(img_request->obj_request_count > 0);
>>         rbd_assert(which != BAD_WHICH);
>>         rbd_assert(which < img_request->obj_request_count);
>>
>> Until then I think you can avoid this by commenting out those
>> assertions.  I'm afraid there will remain a (smaller) window
>> of opportunity for a problem to occur, but I believe commenting
>> those out will help for now.
>>
>> I'm very sorry you're hitting these.  I'll see if I can get
>> a comprehensive fix this weekend.
>>
>> 					-Alex
> 
> Thanks for your help, really.
> 
> By removing those asserts, can I throw any data corruption ?

Data corruption is no more likely with the asserts removed.

They should not fail, and in general they do not, so things
are working properly.  Because of this race condition we are
seeing them fail, on rare occasions.  I understand why this
is happening though, and when it does, this test should avoid
doing any invalid processing of the request:
        if (which != img_request->next_completion)
                goto out;

					-Alex

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Olivier Bonvalet]

Le vendredi 04 avril 2014 à 20:57 -0500, Alex Elder a écrit :
> On 04/04/2014 08:16 PM, Olivier Bonvalet wrote:
> > Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
> >> Hi,
> >>
> >> what can/should I do to help fix that problem ?
> >>
> >> for now, RBD kernel client hang on : 
> >>         Assertion failure in rbd_img_obj_callback() at line 2131:
> >>            rbd_assert(which >= img_request->next_completion);
> >>
> >> or on :
> >>         Assertion failure in rbd_img_obj_callback() at line 2127:
> >>             rbd_assert(img_request != NULL);
> >>
> >>
> >> I have both case at least once per week, on latest 3.13.5 kernels.
> >>
> >> It seems that the problem occurs only on more loaded servers (I have 4
> >> near same servers, and crash occurs on two of them. If I move the VM,
> >> crash follows...).
> >>
> >> Olivier
> >>
> >> --
> > 
> > Hi,
> > 
> > so. After some days without any problems, RBD crashed toonight :
> 
> Unfortunately this could be a symptom of the same sort of race.
> When a object request is removed from its image request's list
> the request count gets decremented.  To be honest, all of these
> assertions in rbd_img_obj_callback() are probably unsafe, at
> least until I get the patch that does proper reference counting
> implemented:
> 
>         rbd_assert(img_request != NULL);
>         rbd_assert(img_request->obj_request_count > 0);
>         rbd_assert(which != BAD_WHICH);
>         rbd_assert(which < img_request->obj_request_count);
> 
> Until then I think you can avoid this by commenting out those
> assertions.  I'm afraid there will remain a (smaller) window
> of opportunity for a problem to occur, but I believe commenting
> those out will help for now.
> 
> I'm very sorry you're hitting these.  I'll see if I can get
> a comprehensive fix this weekend.
> 
> 					-Alex
> 

Hi,

I suppose that I should add :
    if (img_request == NULL) goto out;

Right ?

When commenting the asserts I obtain a NULL pointer dereference :

Apr 25 13:03:15 murmillia kernel: [124049.097927] BUG: unable to handle kernel NULL pointer dereference at 000000000000003c
Apr 25 13:03:15 murmillia kernel: [124049.098008] IP: [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
Apr 25 13:03:15 murmillia kernel: [124049.098056] PGD 0 
Apr 25 13:03:15 murmillia kernel: [124049.098091] Oops: 0002 [#1] SMP 
Apr 25 13:03:15 murmillia kernel: [124049.098133] Modules linked in: cbc rbd libceph xen_gntdev ip6table_mangle ip6t_REJECT ip6table_filter ip6_tables xt_DSCP iptable_mangle xt_LOG xt_physdev ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core i2c_i801 evdev lpc_ich mfd_core ioatdma shpchp ipmi_si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common megaraid_sas ahci libahci isci ehci_pci ehci_hcd libsas usbcore libata igb ixgbe scsi_transport_sas i2c_algo_bit i2c_core usb_common scsi_mod dca ptp pps_core mdio
Apr 25 13:03:15 murmillia kernel: [124049.098695] CPU: 0 PID: 31669 Comm: kworker/0:0 Not tainted 3.13-dae-dom0 #1
Apr 25 13:03:15 murmillia kernel: [124049.098739] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 2.0a 03/11/2013
Apr 25 13:03:15 murmillia kernel: [124049.098809] Workqueue: ceph-msgr con_work [libceph]
Apr 25 13:03:15 murmillia kernel: [124049.098851] task: ffff8802458b38a0 ti: ffff88023cfcc000 task.ti: ffff88023cfcc000
Apr 25 13:03:15 murmillia kernel: [124049.098916] RIP: e030:[<ffffffff8105d922>]  [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
Apr 25 13:03:15 murmillia kernel: [124049.098987] RSP: e02b:ffff88023cfcdce0  EFLAGS: 00010002
Apr 25 13:03:15 murmillia kernel: [124049.099026] RAX: 0000000000010000 RBX: ffff88025749a3c8 RCX: 0000000000002201
Apr 25 13:03:15 murmillia kernel: [124049.099091] RDX: 000000000000003c RSI: ffff88025749a3e0 RDI: 000000000000003c
Apr 25 13:03:15 murmillia kernel: [124049.099154] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000001
Apr 25 13:03:15 murmillia kernel: [124049.099218] R10: ffff88024749d07d R11: ffff8802476929f8 R12: ffff880269f6b701
Apr 25 13:03:15 murmillia kernel: [124049.099281] R13: 00000000ffffffff R14: ffff8802476927c0 R15: 0000000000000000
Apr 25 13:03:15 murmillia kernel: [124049.099349] FS:  00007f01384088e0(0000) GS:ffff88027fc00000(0000) knlGS:0000000000000000
Apr 25 13:03:15 murmillia kernel: [124049.099415] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
Apr 25 13:03:15 murmillia kernel: [124049.099455] CR2: 000000000000003c CR3: 0000000243dec000 CR4: 0000000000042660
Apr 25 13:03:15 murmillia kernel: [124049.099519] Stack:
Apr 25 13:03:15 murmillia kernel: [124049.099549]  ffffffffa032caad 000000000000003c ffff8802476929f8 0000000000002201
Apr 25 13:03:15 murmillia kernel: [124049.099629]  ffff8802411ea218 ffff8802476927b8 ffff880269f6b718 0000000000000000
Apr 25 13:03:15 murmillia kernel: [124049.099708]  ffff8802476927c0 0000000000000000 ffffffffa030b69b 0000000000000025
Apr 25 13:03:15 murmillia kernel: [124049.099786] Call Trace:
Apr 25 13:03:15 murmillia kernel: [124049.099823]  [<ffffffffa032caad>] ? rbd_img_obj_callback+0x56/0x308 [rbd]
Apr 25 13:03:15 murmillia kernel: [124049.099871]  [<ffffffffa030b69b>] ? dispatch+0x3e4/0x55e [libceph]
Apr 25 13:03:15 murmillia kernel: [124049.099915]  [<ffffffffa03060fc>] ? con_work+0xf6e/0x1a65 [libceph]
Apr 25 13:03:15 murmillia kernel: [124049.099959]  [<ffffffff8100122a>] ? xen_hypercall_xen_version+0xa/0x20
Apr 25 13:03:15 murmillia kernel: [124049.100004]  [<ffffffff81005959>] ? xen_force_evtchn_callback+0x9/0xa
Apr 25 13:03:15 murmillia kernel: [124049.100048]  [<ffffffff810484e8>] ? process_one_work+0x15a/0x214
Apr 25 13:03:15 murmillia kernel: [124049.100100]  [<ffffffff8104896c>] ? worker_thread+0x139/0x1de
Apr 25 13:03:15 murmillia kernel: [124049.100141]  [<ffffffff81048833>] ? rescuer_thread+0x26e/0x26e
Apr 25 13:03:15 murmillia kernel: [124049.100183]  [<ffffffff8104d007>] ? kthread+0x9e/0xa6
Apr 25 13:03:15 murmillia kernel: [124049.100223]  [<ffffffff8104cf69>] ? __kthread_parkme+0x55/0x55
Apr 25 13:03:15 murmillia kernel: [124049.100268]  [<ffffffff81372a0c>] ? ret_from_fork+0x7c/0xb0
Apr 25 13:03:15 murmillia kernel: [124049.100309]  [<ffffffff8104cf69>] ? __kthread_parkme+0x55/0x55
Apr 25 13:03:15 murmillia kernel: [124049.100349] Code: d0 f0 0f b1 0f 39 d0 0f 94 c0 0f b6 c0 c3 31 c0 48 81 ff e8 db 36 81 72 0c 31 c0 48 81 ff af df 36 81 0f 92 c0 c3 b8 00 00 01 00 <f0> 0f c1 07 89 c2 c1 ea 10 66 39 c2 89 d1 74 0c 66 8b 07 66 39 
Apr 25 13:03:15 murmillia kernel: [124049.100727] RIP  [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
Apr 25 13:03:15 murmillia kernel: [124049.100773]  RSP <ffff88023cfcdce0>
Apr 25 13:03:15 murmillia kernel: [124049.100807] CR2: 000000000000003c
Apr 25 13:03:15 murmillia kernel: [124049.101120] ---[ end trace 7f81ace5e0aed716 ]---




--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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

[Alex Elder]

On 04/25/2014 06:37 AM, Olivier Bonvalet wrote:
> Le vendredi 04 avril 2014 à 20:57 -0500, Alex Elder a écrit :
>> On 04/04/2014 08:16 PM, Olivier Bonvalet wrote:
>>> Le mardi 25 mars 2014 à 09:39 +0100, Olivier Bonvalet a écrit :
>>>> Hi,
>>>>
>>>> what can/should I do to help fix that problem ?
>>>>
>>>> for now, RBD kernel client hang on : 
>>>>         Assertion failure in rbd_img_obj_callback() at line 2131:
>>>>            rbd_assert(which >= img_request->next_completion);
>>>>
>>>> or on :
>>>>         Assertion failure in rbd_img_obj_callback() at line 2127:
>>>>             rbd_assert(img_request != NULL);
>>>>
>>>>
>>>> I have both case at least once per week, on latest 3.13.5 kernels.
>>>>
>>>> It seems that the problem occurs only on more loaded servers (I have 4
>>>> near same servers, and crash occurs on two of them. If I move the VM,
>>>> crash follows...).
>>>>
>>>> Olivier
>>>>
>>>> --
>>>
>>> Hi,
>>>
>>> so. After some days without any problems, RBD crashed toonight :
>>
>> Unfortunately this could be a symptom of the same sort of race.
>> When a object request is removed from its image request's list
>> the request count gets decremented.  To be honest, all of these
>> assertions in rbd_img_obj_callback() are probably unsafe, at
>> least until I get the patch that does proper reference counting
>> implemented:
>>
>>         rbd_assert(img_request != NULL);
>>         rbd_assert(img_request->obj_request_count > 0);
>>         rbd_assert(which != BAD_WHICH);
>>         rbd_assert(which < img_request->obj_request_count);
>>
>> Until then I think you can avoid this by commenting out those
>> assertions.  I'm afraid there will remain a (smaller) window
>> of opportunity for a problem to occur, but I believe commenting
>> those out will help for now.
>>
>> I'm very sorry you're hitting these.  I'll see if I can get
>> a comprehensive fix this weekend.
>>
>> 					-Alex
>>
> 
> Hi,
> 
> I suppose that I should add :
>     if (img_request == NULL) goto out;
> 
> Right ?

Sure, why not?

To be serious we need to get you a proper fix.  I have one
written (I think I've had it for two weeks) but have been
unable to test it at all.  And this is one I don't want to
just give to a customer to test, I want to make sure it works
before sending it out.

I was hoping we had made the window of vulnerability small
enough that the problem wouldn't occur.  Your new report
shows we're not that lucky.   I'll see what I can do.

					-Alex

> When commenting the asserts I obtain a NULL pointer dereference :
> 
> Apr 25 13:03:15 murmillia kernel: [124049.097927] BUG: unable to handle kernel NULL pointer dereference at 000000000000003c
> Apr 25 13:03:15 murmillia kernel: [124049.098008] IP: [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
> Apr 25 13:03:15 murmillia kernel: [124049.098056] PGD 0 
> Apr 25 13:03:15 murmillia kernel: [124049.098091] Oops: 0002 [#1] SMP 
> Apr 25 13:03:15 murmillia kernel: [124049.098133] Modules linked in: cbc rbd libceph xen_gntdev ip6table_mangle ip6t_REJECT ip6table_filter ip6_tables xt_DSCP iptable_mangle xt_LOG xt_physdev ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables xfs libcrc32c bridge loop iTCO_wdt gpio_ich iTCO_vendor_support serio_raw sb_edac edac_core i2c_i801 evdev lpc_ich mfd_core ioatdma shpchp ipmi_si ipmi_msghandler wmi ac button dm_mod hid_generic usbhid hid sg sd_mod crc_t10dif crct10dif_common megaraid_sas ahci libahci isci ehci_pci ehci_hcd libsas usbcore libata igb ixgbe scsi_transport_sas i2c_algo_bit i2c_core usb_common scsi_mod dca ptp pps_core mdio
> Apr 25 13:03:15 murmillia kernel: [124049.098695] CPU: 0 PID: 31669 Comm: kworker/0:0 Not tainted 3.13-dae-dom0 #1
> Apr 25 13:03:15 murmillia kernel: [124049.098739] Hardware name: Supermicro X9DRW-7TPF+/X9DRW-7TPF+, BIOS 2.0a 03/11/2013
> Apr 25 13:03:15 murmillia kernel: [124049.098809] Workqueue: ceph-msgr con_work [libceph]
> Apr 25 13:03:15 murmillia kernel: [124049.098851] task: ffff8802458b38a0 ti: ffff88023cfcc000 task.ti: ffff88023cfcc000
> Apr 25 13:03:15 murmillia kernel: [124049.098916] RIP: e030:[<ffffffff8105d922>]  [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
> Apr 25 13:03:15 murmillia kernel: [124049.098987] RSP: e02b:ffff88023cfcdce0  EFLAGS: 00010002
> Apr 25 13:03:15 murmillia kernel: [124049.099026] RAX: 0000000000010000 RBX: ffff88025749a3c8 RCX: 0000000000002201
> Apr 25 13:03:15 murmillia kernel: [124049.099091] RDX: 000000000000003c RSI: ffff88025749a3e0 RDI: 000000000000003c
> Apr 25 13:03:15 murmillia kernel: [124049.099154] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000001
> Apr 25 13:03:15 murmillia kernel: [124049.099218] R10: ffff88024749d07d R11: ffff8802476929f8 R12: ffff880269f6b701
> Apr 25 13:03:15 murmillia kernel: [124049.099281] R13: 00000000ffffffff R14: ffff8802476927c0 R15: 0000000000000000
> Apr 25 13:03:15 murmillia kernel: [124049.099349] FS:  00007f01384088e0(0000) GS:ffff88027fc00000(0000) knlGS:0000000000000000
> Apr 25 13:03:15 murmillia kernel: [124049.099415] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
> Apr 25 13:03:15 murmillia kernel: [124049.099455] CR2: 000000000000003c CR3: 0000000243dec000 CR4: 0000000000042660
> Apr 25 13:03:15 murmillia kernel: [124049.099519] Stack:
> Apr 25 13:03:15 murmillia kernel: [124049.099549]  ffffffffa032caad 000000000000003c ffff8802476929f8 0000000000002201
> Apr 25 13:03:15 murmillia kernel: [124049.099629]  ffff8802411ea218 ffff8802476927b8 ffff880269f6b718 0000000000000000
> Apr 25 13:03:15 murmillia kernel: [124049.099708]  ffff8802476927c0 0000000000000000 ffffffffa030b69b 0000000000000025
> Apr 25 13:03:15 murmillia kernel: [124049.099786] Call Trace:
> Apr 25 13:03:15 murmillia kernel: [124049.099823]  [<ffffffffa032caad>] ? rbd_img_obj_callback+0x56/0x308 [rbd]
> Apr 25 13:03:15 murmillia kernel: [124049.099871]  [<ffffffffa030b69b>] ? dispatch+0x3e4/0x55e [libceph]
> Apr 25 13:03:15 murmillia kernel: [124049.099915]  [<ffffffffa03060fc>] ? con_work+0xf6e/0x1a65 [libceph]
> Apr 25 13:03:15 murmillia kernel: [124049.099959]  [<ffffffff8100122a>] ? xen_hypercall_xen_version+0xa/0x20
> Apr 25 13:03:15 murmillia kernel: [124049.100004]  [<ffffffff81005959>] ? xen_force_evtchn_callback+0x9/0xa
> Apr 25 13:03:15 murmillia kernel: [124049.100048]  [<ffffffff810484e8>] ? process_one_work+0x15a/0x214
> Apr 25 13:03:15 murmillia kernel: [124049.100100]  [<ffffffff8104896c>] ? worker_thread+0x139/0x1de
> Apr 25 13:03:15 murmillia kernel: [124049.100141]  [<ffffffff81048833>] ? rescuer_thread+0x26e/0x26e
> Apr 25 13:03:15 murmillia kernel: [124049.100183]  [<ffffffff8104d007>] ? kthread+0x9e/0xa6
> Apr 25 13:03:15 murmillia kernel: [124049.100223]  [<ffffffff8104cf69>] ? __kthread_parkme+0x55/0x55
> Apr 25 13:03:15 murmillia kernel: [124049.100268]  [<ffffffff81372a0c>] ? ret_from_fork+0x7c/0xb0
> Apr 25 13:03:15 murmillia kernel: [124049.100309]  [<ffffffff8104cf69>] ? __kthread_parkme+0x55/0x55
> Apr 25 13:03:15 murmillia kernel: [124049.100349] Code: d0 f0 0f b1 0f 39 d0 0f 94 c0 0f b6 c0 c3 31 c0 48 81 ff e8 db 36 81 72 0c 31 c0 48 81 ff af df 36 81 0f 92 c0 c3 b8 00 00 01 00 <f0> 0f c1 07 89 c2 c1 ea 10 66 39 c2 89 d1 74 0c 66 8b 07 66 39 
> Apr 25 13:03:15 murmillia kernel: [124049.100727] RIP  [<ffffffff8105d922>] do_raw_spin_lock+0x5/0x22
> Apr 25 13:03:15 murmillia kernel: [124049.100773]  RSP <ffff88023cfcdce0>
> Apr 25 13:03:15 murmillia kernel: [124049.100807] CR2: 000000000000003c
> Apr 25 13:03:15 murmillia kernel: [124049.101120] ---[ end trace 7f81ace5e0aed716 ]---
> 
> 
> 
> 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html