Re: Write protected devices, unexpected dm-multipath queueing

Re: Write protected devices, unexpected dm-multipath queueing

[Mike Snitzer]

On Fri, Jan 06 2012 at  2:30pm -0500,
Christophe Varoqui <christophe.varoqui@gmail.com> wrote:

> Hannes, list,
> 
> reading your kernel path there
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=63583cca745f440167bf27877182dc13e19d4bcf
> I wonder if this is expected that a write io on a write protected device
> is returned to the queue ? I would have guessed it qualified as
> TARGET_ERROR, hence not retryable (and not causing path invalidation).
> 
> In the following log the sense code is clearly seen as 
> Sense Key : Data Protect [current]
> Add. Sense: Write protected
> 
> The log is grabbed from a el6 kernel rev. 131 which include the
> mentioned patch (since rev. 110 iirc).
> 
> Care to confirm something is fishy there ?

scsi_check_sense() needs to be trained to return TARGET_ERROR for this
case.

The commit you referenced wasn't meant to have covered _every_ possible
TARGET_ERROR case.  For example, I posted a patch for other TARGET_ERROR
cases here:
http://www.spinics.net/lists/linux-scsi/msg55792.html

> ====
> 
> Jan  6 02:54:20 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 0
> 
> Jan  6 02:54:20 wheeler multipathd: 360000970000292602571533030384444:
> Entering recovery mode: max_retries=5
> 
> Jan  6 02:54:23 wheeler multipathd: 360000970000292602571533030384444:
> sdbq - tur checker reports path is up
> 
> Jan  6 02:54:23 wheeler multipathd: 68:64: reinstated
> 
> Jan  6 02:54:23 wheeler multipathd: 360000970000292602571533030384444:
> queue_if_no_path enabled
> 
> Jan  6 02:54:23 wheeler multipathd: 360000970000292602571533030384444:
> Recovered to normal mode
> 
> Jan  6 02:54:23 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 1
> 
> Jan  6 02:54:23 wheeler kernel: sd 2:0:0:15: [sdbq] Unhandled sense code
> 
> Jan  6 02:54:23 wheeler kernel: sd 2:0:0:15: [sdbq] Result:
> hostbyte=invalid driverbyte=DRIVER_SENSE
> 
> Jan  6 02:54:23 wheeler kernel: sd 2:0:0:15: [sdbq] Sense Key : Data
> Protect [current] 
> 
> Jan  6 02:54:23 wheeler kernel: sd 2:0:0:15: [sdbq] Add. Sense: Write
> protected
> 
> Jan  6 02:54:23 wheeler kernel: sd 2:0:0:15: [sdbq] CDB: Write(10): 2a
> 00 00 00 00 d0 00 00 10 00
> 
> Jan  6 02:54:23 wheeler kernel: end_request: I/O error, dev sdbq, sector
> 208
> 
> Jan  6 02:54:23 wheeler kernel: device-mapper: multipath: Failing path
> 68:64.
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> sdq - tur checker reports path is up
> 
> Jan  6 02:54:24 wheeler multipathd: 65:0: reinstated
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 2
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> sdaq - tur checker reports path is up
> 
> Jan  6 02:54:24 wheeler multipathd: 66:160: reinstated
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 3
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> sdcq - tur checker reports path is up
> 
> Jan  6 02:54:24 wheeler multipathd: 69:224: reinstated
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 4
> 
> Jan  6 02:54:24 wheeler multipathd: 68:64: mark as failed
> 
> Jan  6 02:54:24 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 3
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:0:15: [sdq] Unhandled sense code
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:0:15: [sdq] Result:
> hostbyte=invalid driverbyte=DRIVER_SENSE
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:0:15: [sdq] Sense Key : Data
> Protect [current] 
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:0:15: [sdq] Add. Sense: Write
> protected
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:0:15: [sdq] CDB: Write(10): 2a 00
> 00 00 00 d0 00 00 10 00
> 
> Jan  6 02:54:24 wheeler kernel: end_request: I/O error, dev sdq, sector
> 208
> 
> Jan  6 02:54:24 wheeler kernel: device-mapper: multipath: Failing path
> 65:0.
> 
> Jan  6 02:54:24 wheeler kernel: sd 2:0:1:15: [sdcq] Unhandled sense code
> 
> Jan  6 02:54:24 wheeler kernel: sd 2:0:1:15: [sdcq] Result:
> hostbyte=invalid driverbyte=DRIVER_SENSE
> 
> Jan  6 02:54:24 wheeler kernel: sd 2:0:1:15: [sdcq] Sense Key : Data
> Protect [current] 
> 
> Jan  6 02:54:24 wheeler kernel: sd 2:0:1:15: [sdcq] Add. Sense: Write
> protected
> 
> Jan  6 02:54:24 wheeler kernel: sd 2:0:1:15: [sdcq] CDB: Write(10): 2a
> 00 00 00 00 d0 00 00 10 00
> 
> Jan  6 02:54:24 wheeler kernel: end_request: I/O error, dev sdcq, sector
> 208
> 
> Jan  6 02:54:24 wheeler kernel: device-mapper: multipath: Failing path
> 69:224.
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:1:15: [sdaq] Unhandled sense code
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:1:15: [sdaq] Result:
> hostbyte=invalid driverbyte=DRIVER_SENSE
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:1:15: [sdaq] Sense Key : Data
> Protect [current] 
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:1:15: [sdaq] Add. Sense: Write
> protected
> 
> Jan  6 02:54:24 wheeler kernel: sd 1:0:1:15: [sdaq] CDB: Write(10): 2a
> 00 00 00 00 d0 00 00 10 00
> 
> Jan  6 02:54:24 wheeler kernel: end_request: I/O error, dev sdaq, sector
> 208
> 
> Jan  6 02:54:24 wheeler kernel: device-mapper: multipath: Failing path
> 66:160.
> 
> Jan  6 02:54:25 wheeler multipathd: 65:0: mark as failed
> 
> Jan  6 02:54:25 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 2
> 
> Jan  6 02:54:25 wheeler multipathd: 66:160: mark as failed
> 
> Jan  6 02:54:25 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 1
> 
> Jan  6 02:54:25 wheeler multipathd: 69:224: mark as failed
> 
> Jan  6 02:54:25 wheeler multipathd: 360000970000292602571533030384444:
> Entering recovery mode: max_retries=5
> 
> Jan  6 02:54:25 wheeler multipathd: 360000970000292602571533030384444:
> remaining active paths: 0
> 
> 
> --
> dm-devel mailing list
> dm-devel@redhat.com
> https://www.redhat.com/mailman/listinfo/dm-devel

Re: Write protected devices, unexpected dm-multipath queueing

[Mike Snitzer]

On Fri, Jan 06 2012 at  5:32pm -0500,
Mike Snitzer <snitzer@redhat.com> wrote:

> On Fri, Jan 06 2012 at  2:30pm -0500,
> Christophe Varoqui <christophe.varoqui@gmail.com> wrote:
> 
> > Hannes, list,
> > 
> > reading your kernel path there
> > http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=63583cca745f440167bf27877182dc13e19d4bcf
> > I wonder if this is expected that a write io on a write protected device
> > is returned to the queue ? I would have guessed it qualified as
> > TARGET_ERROR, hence not retryable (and not causing path invalidation).
> > 
> > In the following log the sense code is clearly seen as 
> > Sense Key : Data Protect [current]
> > Add. Sense: Write protected
> > 
> > The log is grabbed from a el6 kernel rev. 131 which include the
> > mentioned patch (since rev. 110 iirc).
> > 
> > Care to confirm something is fishy there ?
> 
> scsi_check_sense() needs to be trained to return TARGET_ERROR for this
> case.
> 
> The commit you referenced wasn't meant to have covered _every_ possible
> TARGET_ERROR case.

Hmm, but looking closer that commit _does_ return TARGET_ERROR for
DATA_PROTECT.

I need to dig deeper, but I think Hannes gets back to work on Monday.

Mike

Re: Write protected devices, unexpected dm-multipath queueing

[Mike Snitzer]

On Fri, Jan 06 2012 at  5:55pm -0500,
Mike Snitzer <snitzer@redhat.com> wrote:

> On Fri, Jan 06 2012 at  5:32pm -0500,
> Mike Snitzer <snitzer@redhat.com> wrote:
> 
> > On Fri, Jan 06 2012 at  2:30pm -0500,
> > Christophe Varoqui <christophe.varoqui@gmail.com> wrote:
> > 
> > > Hannes, list,
> > > 
> > > reading your kernel path there
> > > http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=63583cca745f440167bf27877182dc13e19d4bcf
> > > I wonder if this is expected that a write io on a write protected device
> > > is returned to the queue ? I would have guessed it qualified as
> > > TARGET_ERROR, hence not retryable (and not causing path invalidation).
> > > 
> > > In the following log the sense code is clearly seen as 
> > > Sense Key : Data Protect [current]
> > > Add. Sense: Write protected
> > > 
> > > The log is grabbed from a el6 kernel rev. 131 which include the
> > > mentioned patch (since rev. 110 iirc).
> > > 
> > > Care to confirm something is fishy there ?

Aha, now I remember, I applied all the changes for differentiated SCSI
IO errors for -131.el6 (aka RHEL6.1) _except_ I overlooked one disjoint
yet crucial commit that went upstream much earlier, see this one-liner:
http://git.kernel.org/linus/ad63082626f99651d261ccd8698ce4e997362f7e

So the code for differentiated IO errors was dormant in RHEL6.1, it was
noticed before 6.1 GA'd but was deemed too risky to enable so late in
the 6.1 release cycle.  It has since been enabled in RHEL6.2.

And yes it was a pretty embarassing oversight at the time... now you've
allowed me to relive that embarassment ;)

Long story short, apply that patch or upgrade to the RHEL6.2 kernel.

HTH,
Mike

Re: Write protected devices, unexpected dm-multipath queueing

[Christophe Varoqui]

On ven., 2012-01-06 at 18:20 -0500, Mike Snitzer wrote:
> On Fri, Jan 06 2012 at  5:55pm -0500,
> Mike Snitzer <snitzer@redhat.com> wrote:
> 
> > On Fri, Jan 06 2012 at  5:32pm -0500,
> > Mike Snitzer <snitzer@redhat.com> wrote:
> > 
> > > On Fri, Jan 06 2012 at  2:30pm -0500,
> > > Christophe Varoqui <christophe.varoqui@gmail.com> wrote:
> > > 
> > > > Hannes, list,
> > > > 
> > > > reading your kernel path there
> > > > http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=63583cca745f440167bf27877182dc13e19d4bcf
> > > > I wonder if this is expected that a write io on a write protected device
> > > > is returned to the queue ? I would have guessed it qualified as
> > > > TARGET_ERROR, hence not retryable (and not causing path invalidation).
> > > > 
> > > > In the following log the sense code is clearly seen as 
> > > > Sense Key : Data Protect [current]
> > > > Add. Sense: Write protected
> > > > 
> > > > The log is grabbed from a el6 kernel rev. 131 which include the
> > > > mentioned patch (since rev. 110 iirc).
> > > > 
> > > > Care to confirm something is fishy there ?
> 
> Aha, now I remember, I applied all the changes for differentiated SCSI
> IO errors for -131.el6 (aka RHEL6.1) _except_ I overlooked one disjoint
> yet crucial commit that went upstream much earlier, see this one-liner:
> http://git.kernel.org/linus/ad63082626f99651d261ccd8698ce4e997362f7e
> 
> So the code for differentiated IO errors was dormant in RHEL6.1, it was
> noticed before 6.1 GA'd but was deemed too risky to enable so late in
> the 6.1 release cycle.  It has since been enabled in RHEL6.2.
> 
> And yes it was a pretty embarassing oversight at the time... now you've
> allowed me to relive that embarassment ;)
> 
> Long story short, apply that patch or upgrade to the RHEL6.2 kernel.

Thank you for the explanation, and sorry for the ambarassment. By bad,
for not having tried the upgrade before nosing around ;)

Regards,
cvaroqui

Re: Write protected devices, unexpected dm-multipath queueing

[Hannes Reinecke]

On 01/06/2012 11:32 PM, Mike Snitzer wrote:
> On Fri, Jan 06 2012 at  2:30pm -0500,
> Christophe Varoqui <christophe.varoqui@gmail.com> wrote:
> 
>> Hannes, list,
>>
>> reading your kernel path there
>> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=63583cca745f440167bf27877182dc13e19d4bcf
>> I wonder if this is expected that a write io on a write protected device
>> is returned to the queue ? I would have guessed it qualified as
>> TARGET_ERROR, hence not retryable (and not causing path invalidation).
>>
>> In the following log the sense code is clearly seen as 
>> Sense Key : Data Protect [current]
>> Add. Sense: Write protected
>>
>> The log is grabbed from a el6 kernel rev. 131 which include the
>> mentioned patch (since rev. 110 iirc).
>>
>> Care to confirm something is fishy there ?
> 
> scsi_check_sense() needs to be trained to return TARGET_ERROR for this
> case.
> 
> The commit you referenced wasn't meant to have covered _every_ possible
> TARGET_ERROR case.  For example, I posted a patch for other TARGET_ERROR
> cases here:
> http://www.spinics.net/lists/linux-scsi/msg55792.html
> 
Yes, that's correct. We'll need to check for this case, too.

I'll be sending a patch.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html