Write protected devices, unexpected dm-multipath queueing

Write protected devices, unexpected dm-multipath queueing

[Christophe Varoqui]

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 ?

Regards,
cvaroqui

====

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

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