Re: SCSI regression in 4.11
On Thu, 02 Mar 2017 11:18:23 -0800
James Bottomley wrote:
> On March 2, 2017 11:05:05 AM PST, Stephen Hemminger
> wrote:
> >On Thu, 02 Mar 2017 10:36:17 -0800
> >James Bottomley wrote:
> >
> >> On March 2, 2017 10:23:24 AM PST, Stephen Hemminger
> > wrote:
> >> >On Thu, 2 Mar 2017 14:25:14 +0100
> >> >Hannes Reinecke wrote:
> >> >
> >> >> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
> >> >> > On Thu, 2 Mar 2017 01:56:15 +0100
> >> >> > Christoph Hellwig wrote:
> >> >> >
> >> >> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig
> >wrote:
> >> >
> >> >> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger
> >> >wrote:
> >> >> >
> >>
> >>
> >> http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> >>
> >> >
> >> >>
> >> >> It appears that is already in the code I am testing in
> >> >linux-next...
> >> >> >>>
> >> >> >>> It's in -next now, but it wasn't at the time you reported the
> >
> >> >bug.
> >> >> >>>
> >> >> >>> And it would sortof explain the bug if the INQUIRY data is
> >> >correct
> >> >> >>> in the scatterlist, but we ignore it, given that
> >scsi_probe_lun
> >> >> >>> ignores the result based on sense data.
> >> >> >>>
> >> >> >>> Can you check what happens with the horrible hack below:
> >> >> >>
> >> >> >> Strike that - we're checking result later, so this can't be the
> >
> >> >case.
> >> >> >>
> >> >> >> Now the other interesting thing is the memset in
> >__scsi_exectute,
> >> >> >> which looks very suspicious. Try the following please:
> >> >> >>
> >> >> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> >> >> >> index 3e32dc954c3c..22f4fb550561 100644
> >> >> >> --- a/drivers/scsi/scsi_lib.c
> >> >> >> +++ b/drivers/scsi/scsi_lib.c
> >> >> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct
> >scsi_device
> >> >*sdev, const unsigned char *cmd,
> >> >> >> * and prevent security leaks by zeroing out the excess data.
> >> >> >> */
> >> >> >> if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
> >> >> >> -memset(buffer + (bufflen - rq->resid_len), 0,
> >rq->resid_len);
> >> >> >> +// memset(buffer + (bufflen - rq->resid_len), 0,
> >rq->resid_len);
> >> >> >> +printk_ratelimited("%s: got resid %d\n", __func__,
> >> >rq->resid_len);
> >> >> >>
> >> >> >> if (resid)
> >> >> >> *resid = rq->resid_len;
> >> >> >
> >> >> >
> >> >> > Still fails but does print resid on some of the later INQUIRY
> >> >commands (not the initial one).
> >> >> >
> >> >> Can you test what happens if you blank out the storvsc_drv
> >> >workaround:
> >> >>
> >> >> diff --git a/drivers/scsi/storvsc_drv.c
> >b/drivers/scsi/storvsc_drv.c
> >> >> index 585e54f..c36f42d 100644
> >> >> --- a/drivers/scsi/storvsc_drv.c
> >> >> +++ b/drivers/scsi/storvsc_drv.c
> >> >> @@ -1060,13 +1060,13 @@ static void
> >storvsc_on_io_completion(struct
> >> >> storvsc_device *stor_device,
> >> >> * We do this so we can distinguish truly fatal failues
> >> >> * (srb status == 0x4) and off-line the device in that
> >case.
> >> >> */
> >> >> -
> >> >> +#if 0
> >> >> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
> >> >> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
> >> >> vstor_packet->vm_srb.scsi_status = 0;
> >> >> vstor_packet->vm_srb.srb_status =
> >> >SRB_STATUS_SUCCESS;
> >> >> }
> >> >> -
> >> >> +#endif
> >> >>
> >> >> /* Copy over the status...etc */
> >> >> stor_pkt->vm_srb.scsi_status =
> >> >vstor_packet->vm_srb.scsi_status;
> >> >>
> >> >> It might thappen that we're fail to interpret the 'Device not
> >> >present'
> >> >> status correctly (which will happen for non-connected DVDs)
> >causing
> >> >the
> >> >> SCSI stack to make incorrect decisions later on.
> >> >>
> >> >> Cheers,
> >> >>
> >> >> Hannes
> >> >
> >> >There are several oddities about the host SCSI interface that I see:
> >> > 1. The host bus seems to report up to 6 devices even though only 2
> >are
> >> > present (Disk and CDROM).
> >> >2. The CDROM emulation doesn't report the same status as a real
> >device.
> >> > 3. The host emulation of SCSI doesn't support all the page codes
> >which
> >> > is why there is the hack.
> >> >
> >> >But as James said, these don't appear to be related to the failure
> >> >because
> >> >the code worked before and only in post 4.11 merege is there a
> >problem.
> >>
> >> Your wait for the hang trace is the most suggestive. It says we're
> >waiting for a partition read to the spurious device. Previously this
> >would have failed or timed out, so this seems to be the root cause.
> >>
> >> James
> >>
Re: SCSI regression in 4.11
On March 2, 2017 10:23:24 AM PST, Stephen Hemminger
wrote:
>On Thu, 2 Mar 2017 14:25:14 +0100
>Hannes Reinecke wrote:
>
>> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
>> > On Thu, 2 Mar 2017 01:56:15 +0100
>> > Christoph Hellwig wrote:
>> >
>> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
>
>> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger
>wrote:
>> >
>
> http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
>
>>
>> It appears that is already in the code I am testing in
>linux-next...
>> >>>
>> >>> It's in -next now, but it wasn't at the time you reported the
>bug.
>> >>>
>> >>> And it would sortof explain the bug if the INQUIRY data is
>correct
>> >>> in the scatterlist, but we ignore it, given that scsi_probe_lun
>> >>> ignores the result based on sense data.
>> >>>
>> >>> Can you check what happens with the horrible hack below:
>> >>
>> >> Strike that - we're checking result later, so this can't be the
>case.
>> >>
>> >> Now the other interesting thing is the memset in __scsi_exectute,
>> >> which looks very suspicious. Try the following please:
>> >>
>> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
>> >> index 3e32dc954c3c..22f4fb550561 100644
>> >> --- a/drivers/scsi/scsi_lib.c
>> >> +++ b/drivers/scsi/scsi_lib.c
>> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device
>*sdev, const unsigned char *cmd,
>> >>* and prevent security leaks by zeroing out the excess data.
>> >>*/
>> >> if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
>> >> - memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
>> >> +// memset(buffer + (bufflen - rq->resid_len), 0,
>> >> rq->resid_len);
>> >> + printk_ratelimited("%s: got resid %d\n", __func__,
>rq->resid_len);
>> >>
>> >> if (resid)
>> >> *resid = rq->resid_len;
>> >
>> >
>> > Still fails but does print resid on some of the later INQUIRY
>commands (not the initial one).
>> >
>> Can you test what happens if you blank out the storvsc_drv
>workaround:
>>
>> diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
>> index 585e54f..c36f42d 100644
>> --- a/drivers/scsi/storvsc_drv.c
>> +++ b/drivers/scsi/storvsc_drv.c
>> @@ -1060,13 +1060,13 @@ static void storvsc_on_io_completion(struct
>> storvsc_device *stor_device,
>> * We do this so we can distinguish truly fatal failues
>> * (srb status == 0x4) and off-line the device in that case.
>> */
>> -
>> +#if 0
>> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
>> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
>> vstor_packet->vm_srb.scsi_status = 0;
>> vstor_packet->vm_srb.srb_status =
>SRB_STATUS_SUCCESS;
>> }
>> -
>> +#endif
>>
>> /* Copy over the status...etc */
>> stor_pkt->vm_srb.scsi_status =
>vstor_packet->vm_srb.scsi_status;
>>
>> It might thappen that we're fail to interpret the 'Device not
>present'
>> status correctly (which will happen for non-connected DVDs) causing
>the
>> SCSI stack to make incorrect decisions later on.
>>
>> Cheers,
>>
>> Hannes
>
>There are several oddities about the host SCSI interface that I see:
> 1. The host bus seems to report up to 6 devices even though only 2 are
> present (Disk and CDROM).
>2. The CDROM emulation doesn't report the same status as a real device.
> 3. The host emulation of SCSI doesn't support all the page codes which
> is why there is the hack.
>
>But as James said, these don't appear to be related to the failure
>because
>the code worked before and only in post 4.11 merege is there a problem.
Your wait for the hang trace is the most suggestive. It says we're waiting
for a partition read to the spurious device. Previously this would have failed
or timed out, so this seems to be the root cause.
James
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.
Re: SCSI regression in 4.11
On March 2, 2017 11:05:05 AM PST, Stephen Hemminger
wrote:
>On Thu, 02 Mar 2017 10:36:17 -0800
>James Bottomley wrote:
>
>> On March 2, 2017 10:23:24 AM PST, Stephen Hemminger
> wrote:
>> >On Thu, 2 Mar 2017 14:25:14 +0100
>> >Hannes Reinecke wrote:
>> >
>> >> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
>> >> > On Thu, 2 Mar 2017 01:56:15 +0100
>> >> > Christoph Hellwig wrote:
>> >> >
>> >> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig
>wrote:
>> >
>> >> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger
>> >wrote:
>> >> >
>>
>>
>> http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
>> >
>> >>
>> >> It appears that is already in the code I am testing in
>> >linux-next...
>> >> >>>
>> >> >>> It's in -next now, but it wasn't at the time you reported the
>
>> >bug.
>> >> >>>
>> >> >>> And it would sortof explain the bug if the INQUIRY data is
>> >correct
>> >> >>> in the scatterlist, but we ignore it, given that
>scsi_probe_lun
>> >> >>> ignores the result based on sense data.
>> >> >>>
>> >> >>> Can you check what happens with the horrible hack below:
>> >> >>
>> >> >> Strike that - we're checking result later, so this can't be the
>
>> >case.
>> >> >>
>> >> >> Now the other interesting thing is the memset in
>__scsi_exectute,
>> >> >> which looks very suspicious. Try the following please:
>> >> >>
>> >> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
>> >> >> index 3e32dc954c3c..22f4fb550561 100644
>> >> >> --- a/drivers/scsi/scsi_lib.c
>> >> >> +++ b/drivers/scsi/scsi_lib.c
>> >> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct
>scsi_device
>> >*sdev, const unsigned char *cmd,
>> >> >> * and prevent security leaks by zeroing out the excess data.
>> >> >> */
>> >> >>if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
>> >> >> - memset(buffer + (bufflen - rq->resid_len), 0,
>rq->resid_len);
>> >> >> +//memset(buffer + (bufflen - rq->resid_len), 0,
>rq->resid_len);
>> >> >> + printk_ratelimited("%s: got resid %d\n", __func__,
>> >rq->resid_len);
>> >> >>
>> >> >>if (resid)
>> >> >>*resid = rq->resid_len;
>> >> >
>> >> >
>> >> > Still fails but does print resid on some of the later INQUIRY
>> >commands (not the initial one).
>> >> >
>> >> Can you test what happens if you blank out the storvsc_drv
>> >workaround:
>> >>
>> >> diff --git a/drivers/scsi/storvsc_drv.c
>b/drivers/scsi/storvsc_drv.c
>> >> index 585e54f..c36f42d 100644
>> >> --- a/drivers/scsi/storvsc_drv.c
>> >> +++ b/drivers/scsi/storvsc_drv.c
>> >> @@ -1060,13 +1060,13 @@ static void
>storvsc_on_io_completion(struct
>> >> storvsc_device *stor_device,
>> >> * We do this so we can distinguish truly fatal failues
>> >> * (srb status == 0x4) and off-line the device in that
>case.
>> >> */
>> >> -
>> >> +#if 0
>> >> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
>> >> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
>> >> vstor_packet->vm_srb.scsi_status = 0;
>> >> vstor_packet->vm_srb.srb_status =
>> >SRB_STATUS_SUCCESS;
>> >> }
>> >> -
>> >> +#endif
>> >>
>> >> /* Copy over the status...etc */
>> >> stor_pkt->vm_srb.scsi_status =
>> >vstor_packet->vm_srb.scsi_status;
>> >>
>> >> It might thappen that we're fail to interpret the 'Device not
>> >present'
>> >> status correctly (which will happen for non-connected DVDs)
>causing
>> >the
>> >> SCSI stack to make incorrect decisions later on.
>> >>
>> >> Cheers,
>> >>
>> >> Hannes
>> >
>> >There are several oddities about the host SCSI interface that I see:
>> > 1. The host bus seems to report up to 6 devices even though only 2
>are
>> > present (Disk and CDROM).
>> >2. The CDROM emulation doesn't report the same status as a real
>device.
>> > 3. The host emulation of SCSI doesn't support all the page codes
>which
>> > is why there is the hack.
>> >
>> >But as James said, these don't appear to be related to the failure
>> >because
>> >the code worked before and only in post 4.11 merege is there a
>problem.
>>
>> Your wait for the hang trace is the most suggestive. It says we're
>waiting for a partition read to the spurious device. Previously this
>would have failed or timed out, so this seems to be the root cause.
>>
>> James
>>
>>
>
>Where is the number of valid LUN's determined during the scan process?
Depends. If you can do a report lun scan then that's definitive. You seem to
be probing (SCSI_probe_and_add_lun) and you make us think there's something
there by responding wrongly to the initial inquiry.
James
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.
Re: SCSI regression in 4.11
On Thu, 02 Mar 2017 10:36:17 -0800
James Bottomley wrote:
> On March 2, 2017 10:23:24 AM PST, Stephen Hemminger
> wrote:
> >On Thu, 2 Mar 2017 14:25:14 +0100
> >Hannes Reinecke wrote:
> >
> >> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
> >> > On Thu, 2 Mar 2017 01:56:15 +0100
> >> > Christoph Hellwig wrote:
> >> >
> >> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
> >
> >> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger
> >wrote:
> >> >
> >
> > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> >
> >>
> >> It appears that is already in the code I am testing in
> >linux-next...
> >> >>>
> >> >>> It's in -next now, but it wasn't at the time you reported the
> >bug.
> >> >>>
> >> >>> And it would sortof explain the bug if the INQUIRY data is
> >correct
> >> >>> in the scatterlist, but we ignore it, given that scsi_probe_lun
> >> >>> ignores the result based on sense data.
> >> >>>
> >> >>> Can you check what happens with the horrible hack below:
> >> >>
> >> >> Strike that - we're checking result later, so this can't be the
> >case.
> >> >>
> >> >> Now the other interesting thing is the memset in __scsi_exectute,
> >> >> which looks very suspicious. Try the following please:
> >> >>
> >> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> >> >> index 3e32dc954c3c..22f4fb550561 100644
> >> >> --- a/drivers/scsi/scsi_lib.c
> >> >> +++ b/drivers/scsi/scsi_lib.c
> >> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device
> >*sdev, const unsigned char *cmd,
> >> >> * and prevent security leaks by zeroing out the excess data.
> >> >> */
> >> >> if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
> >> >> - memset(buffer + (bufflen - rq->resid_len), 0,
> >> >> rq->resid_len);
> >> >> +// memset(buffer + (bufflen - rq->resid_len), 0,
> >> >> rq->resid_len);
> >> >> + printk_ratelimited("%s: got resid %d\n", __func__,
> >rq->resid_len);
> >> >>
> >> >> if (resid)
> >> >> *resid = rq->resid_len;
> >> >
> >> >
> >> > Still fails but does print resid on some of the later INQUIRY
> >commands (not the initial one).
> >> >
> >> Can you test what happens if you blank out the storvsc_drv
> >workaround:
> >>
> >> diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
> >> index 585e54f..c36f42d 100644
> >> --- a/drivers/scsi/storvsc_drv.c
> >> +++ b/drivers/scsi/storvsc_drv.c
> >> @@ -1060,13 +1060,13 @@ static void storvsc_on_io_completion(struct
> >> storvsc_device *stor_device,
> >> * We do this so we can distinguish truly fatal failues
> >> * (srb status == 0x4) and off-line the device in that case.
> >> */
> >> -
> >> +#if 0
> >> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
> >> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
> >> vstor_packet->vm_srb.scsi_status = 0;
> >> vstor_packet->vm_srb.srb_status =
> >SRB_STATUS_SUCCESS;
> >> }
> >> -
> >> +#endif
> >>
> >> /* Copy over the status...etc */
> >> stor_pkt->vm_srb.scsi_status =
> >vstor_packet->vm_srb.scsi_status;
> >>
> >> It might thappen that we're fail to interpret the 'Device not
> >present'
> >> status correctly (which will happen for non-connected DVDs) causing
> >the
> >> SCSI stack to make incorrect decisions later on.
> >>
> >> Cheers,
> >>
> >> Hannes
> >
> >There are several oddities about the host SCSI interface that I see:
> > 1. The host bus seems to report up to 6 devices even though only 2 are
> > present (Disk and CDROM).
> >2. The CDROM emulation doesn't report the same status as a real device.
> > 3. The host emulation of SCSI doesn't support all the page codes which
> > is why there is the hack.
> >
> >But as James said, these don't appear to be related to the failure
> >because
> >the code worked before and only in post 4.11 merege is there a problem.
>
> Your wait for the hang trace is the most suggestive. It says we're waiting
> for a partition read to the spurious device. Previously this would have
> failed or timed out, so this seems to be the root cause.
>
> James
>
>
Where is the number of valid LUN's determined during the scan process?
Re: SCSI regression in 4.11
On Thu, 2 Mar 2017 14:25:14 +0100
Hannes Reinecke wrote:
> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
> > On Thu, 2 Mar 2017 01:56:15 +0100
> > Christoph Hellwig wrote:
> >
> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> >
> > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> >
>
> It appears that is already in the code I am testing in linux-next...
> >>>
> >>> It's in -next now, but it wasn't at the time you reported the bug.
> >>>
> >>> And it would sortof explain the bug if the INQUIRY data is correct
> >>> in the scatterlist, but we ignore it, given that scsi_probe_lun
> >>> ignores the result based on sense data.
> >>>
> >>> Can you check what happens with the horrible hack below:
> >>
> >> Strike that - we're checking result later, so this can't be the case.
> >>
> >> Now the other interesting thing is the memset in __scsi_exectute,
> >> which looks very suspicious. Try the following please:
> >>
> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> >> index 3e32dc954c3c..22f4fb550561 100644
> >> --- a/drivers/scsi/scsi_lib.c
> >> +++ b/drivers/scsi/scsi_lib.c
> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device *sdev,
> >> const unsigned char *cmd,
> >> * and prevent security leaks by zeroing out the excess data.
> >> */
> >>if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
> >> - memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
> >> +//memset(buffer + (bufflen - rq->resid_len), 0,
> >> rq->resid_len);
> >> + printk_ratelimited("%s: got resid %d\n", __func__,
> >> rq->resid_len);
> >>
> >>if (resid)
> >>*resid = rq->resid_len;
> >
> >
> > Still fails but does print resid on some of the later INQUIRY commands (not
> > the initial one).
> >
> Can you test what happens if you blank out the storvsc_drv workaround:
>
> diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
> index 585e54f..c36f42d 100644
> --- a/drivers/scsi/storvsc_drv.c
> +++ b/drivers/scsi/storvsc_drv.c
> @@ -1060,13 +1060,13 @@ static void storvsc_on_io_completion(struct
> storvsc_device *stor_device,
> * We do this so we can distinguish truly fatal failues
> * (srb status == 0x4) and off-line the device in that case.
> */
> -
> +#if 0
> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
> vstor_packet->vm_srb.scsi_status = 0;
> vstor_packet->vm_srb.srb_status = SRB_STATUS_SUCCESS;
> }
> -
> +#endif
>
> /* Copy over the status...etc */
> stor_pkt->vm_srb.scsi_status = vstor_packet->vm_srb.scsi_status;
>
> It might thappen that we're fail to interpret the 'Device not present'
> status correctly (which will happen for non-connected DVDs) causing the
> SCSI stack to make incorrect decisions later on.
>
> Cheers,
>
> Hannes
There are several oddities about the host SCSI interface that I see:
1. The host bus seems to report up to 6 devices even though only 2 are
present (Disk and CDROM).
2. The CDROM emulation doesn't report the same status as a real device.
3. The host emulation of SCSI doesn't support all the page codes which
is why there is the hack.
But as James said, these don't appear to be related to the failure because
the code worked before and only in post 4.11 merege is there a problem.
Re: SCSI regression in 4.11
On Thu, 2 Mar 2017 14:25:14 +0100
Hannes Reinecke wrote:
> On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
> > On Thu, 2 Mar 2017 01:56:15 +0100
> > Christoph Hellwig wrote:
> >
> >> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
> >>> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> >
> > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> >
>
> It appears that is already in the code I am testing in linux-next...
> >>>
> >>> It's in -next now, but it wasn't at the time you reported the bug.
> >>>
> >>> And it would sortof explain the bug if the INQUIRY data is correct
> >>> in the scatterlist, but we ignore it, given that scsi_probe_lun
> >>> ignores the result based on sense data.
> >>>
> >>> Can you check what happens with the horrible hack below:
> >>
> >> Strike that - we're checking result later, so this can't be the case.
> >>
> >> Now the other interesting thing is the memset in __scsi_exectute,
> >> which looks very suspicious. Try the following please:
> >>
> >> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> >> index 3e32dc954c3c..22f4fb550561 100644
> >> --- a/drivers/scsi/scsi_lib.c
> >> +++ b/drivers/scsi/scsi_lib.c
> >> @@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device *sdev,
> >> const unsigned char *cmd,
> >> * and prevent security leaks by zeroing out the excess data.
> >> */
> >>if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
> >> - memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
> >> +//memset(buffer + (bufflen - rq->resid_len), 0,
> >> rq->resid_len);
> >> + printk_ratelimited("%s: got resid %d\n", __func__,
> >> rq->resid_len);
> >>
> >>if (resid)
> >>*resid = rq->resid_len;
> >
> >
> > Still fails but does print resid on some of the later INQUIRY commands (not
> > the initial one).
> >
> Can you test what happens if you blank out the storvsc_drv workaround:
>
> diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
> index 585e54f..c36f42d 100644
> --- a/drivers/scsi/storvsc_drv.c
> +++ b/drivers/scsi/storvsc_drv.c
> @@ -1060,13 +1060,13 @@ static void storvsc_on_io_completion(struct
> storvsc_device *stor_device,
> * We do this so we can distinguish truly fatal failues
> * (srb status == 0x4) and off-line the device in that case.
> */
> -
> +#if 0
> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
> vstor_packet->vm_srb.scsi_status = 0;
> vstor_packet->vm_srb.srb_status = SRB_STATUS_SUCCESS;
> }
> -
> +#endif
>
> /* Copy over the status...etc */
> stor_pkt->vm_srb.scsi_status = vstor_packet->vm_srb.scsi_status;
>
> It might thappen that we're fail to interpret the 'Device not present'
> status correctly (which will happen for non-connected DVDs) causing the
> SCSI stack to make incorrect decisions later on.
>
> Cheers,
>
> Hannes
Makes no difference, that was one of the first things I tried (and just tried
again).
Re: SCSI regression in 4.11
On 03/02/2017 02:40 AM, Stephen Hemminger wrote:
On Thu, 2 Mar 2017 01:56:15 +0100
Christoph Hellwig wrote:
On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
It appears that is already in the code I am testing in linux-next...
It's in -next now, but it wasn't at the time you reported the bug.
And it would sortof explain the bug if the INQUIRY data is correct
in the scatterlist, but we ignore it, given that scsi_probe_lun
ignores the result based on sense data.
Can you check what happens with the horrible hack below:
Strike that - we're checking result later, so this can't be the case.
Now the other interesting thing is the memset in __scsi_exectute,
which looks very suspicious. Try the following please:
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 3e32dc954c3c..22f4fb550561 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device *sdev, const
unsigned char *cmd,
* and prevent security leaks by zeroing out the excess data.
*/
if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
- memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
+// memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
+ printk_ratelimited("%s: got resid %d\n", __func__,
rq->resid_len);
if (resid)
*resid = rq->resid_len;
Still fails but does print resid on some of the later INQUIRY commands (not the
initial one).
Can you test what happens if you blank out the storvsc_drv workaround:
diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
index 585e54f..c36f42d 100644
--- a/drivers/scsi/storvsc_drv.c
+++ b/drivers/scsi/storvsc_drv.c
@@ -1060,13 +1060,13 @@ static void storvsc_on_io_completion(struct
storvsc_device *stor_device,
* We do this so we can distinguish truly fatal failues
* (srb status == 0x4) and off-line the device in that case.
*/
-
+#if 0
if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
(stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
vstor_packet->vm_srb.scsi_status = 0;
vstor_packet->vm_srb.srb_status = SRB_STATUS_SUCCESS;
}
-
+#endif
/* Copy over the status...etc */
stor_pkt->vm_srb.scsi_status = vstor_packet->vm_srb.scsi_status;
It might thappen that we're fail to interpret the 'Device not present'
status correctly (which will happen for non-connected DVDs) causing the
SCSI stack to make incorrect decisions later on.
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries & Storage
h...@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)
Re: SCSI regression in 4.11
On Thu, 2 Mar 2017 01:56:15 +0100
Christoph Hellwig wrote:
> On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
> > On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> > > >
> > > > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> > > >
> > >
> > > It appears that is already in the code I am testing in linux-next...
> >
> > It's in -next now, but it wasn't at the time you reported the bug.
> >
> > And it would sortof explain the bug if the INQUIRY data is correct
> > in the scatterlist, but we ignore it, given that scsi_probe_lun
> > ignores the result based on sense data.
> >
> > Can you check what happens with the horrible hack below:
>
> Strike that - we're checking result later, so this can't be the case.
>
> Now the other interesting thing is the memset in __scsi_exectute,
> which looks very suspicious. Try the following please:
>
> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> index 3e32dc954c3c..22f4fb550561 100644
> --- a/drivers/scsi/scsi_lib.c
> +++ b/drivers/scsi/scsi_lib.c
> @@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device *sdev, const
> unsigned char *cmd,
>* and prevent security leaks by zeroing out the excess data.
>*/
> if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
> - memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
> +// memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
> + printk_ratelimited("%s: got resid %d\n", __func__,
> rq->resid_len);
>
> if (resid)
> *resid = rq->resid_len;
Still fails but does print resid on some of the later INQUIRY commands (not the
initial one).
[1.222728] scsi host0: storvsc_host_t
[1.230120] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x1 length 36
[1.235358] scsi host1: storvsc_host_t
[1.238629] hv_storvsc: payload size 288 count 1 offset 3840 len 36 pfn
0x1f1ef2
[1.241127] hv_storvsc: sg 0: phys 0x1f1ef2000 virt 905db1ef2000 offset
0xf00 length 36
[1.242422] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x1 length 36
[1.242423] hv_storvsc: payload size 288 count 1 offset 3328 len 36 pfn
0x1f112b
[1.242425] hv_storvsc: sg 0: phys 0x1f112b000 virt 905db112b000 offset
0xd00 length 36
[1.242427] data: : 05 80 00 02 1f 00 00 00 4d 73 66 74 20 20 20 20
Msft
[1.242427] data: 0010: 56 69 72 74 75 61 6c 20 44 56 44 2d 52 4f 4d 20
Virtual DVD-ROM
[1.242428] data: 0020: 31 2e 30 20
1.0
[1.242456] scsi 1:0:0:0: CD-ROMMsft Virtual DVD-ROM 1.0
PQ: 0 ANSI: 0
[1.242705] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x20 length 36
[1.242706] hv_storvsc: payload size 288 count 1 offset 2816 len 36 pfn
0x1f112b
[1.242707] hv_storvsc: sg 0: phys 0x1f112b000 virt 905db112b000 offset
0xb00 length 36
[1.242708] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.242709] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.242709] data: 0020: 00 00 00 00
[1.242730] scsi host1: scsi scan: INQUIRY result too short (5), using 36
[1.242732] scsi 1:0:0:1: Direct-Access
PQ: 0 ANSI: 0
[1.242982] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x20 length 36
[1.242983] hv_storvsc: payload size 288 count 1 offset 768 len 36 pfn
0x1f1129
[1.242984] hv_storvsc: sg 0: phys 0x1f1129000 virt 905db1129000 offset
0x300 length 36
[1.242985] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.242986] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.242986] data: 0020: 00 00 00 00
[1.243003] scsi 1:0:0:2: Direct-Access
PQ: 0 ANSI: 0
[1.244180] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x20 length 36
[1.244181] hv_storvsc: payload size 288 count 1 offset 2048 len 36 pfn
0x1f1128
[1.244181] hv_storvsc: sg 0: phys 0x1f1128000 virt 905db1128000 offset
0x800 length 36
[1.244182] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.244183] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1.244183] data: 0020: 00 00 00 00
[1.244202] scsi 1:0:0:3: Direct-Access
PQ: 0 ANSI: 0
[1.244463] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status
0x20 length 36
[1.244463] hv_storvsc: payload size 288 count 1 offset 2560 len
Re: SCSI regression in 4.11
On Thu, 2 Mar 2017 01:01:35 +0100
Christoph Hellwig wrote:
> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> > >
> > > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> > >
> >
> > It appears that is already in the code I am testing in linux-next...
>
> It's in -next now, but it wasn't at the time you reported the bug.
>
> And it would sortof explain the bug if the INQUIRY data is correct
> in the scatterlist, but we ignore it, given that scsi_probe_lun
> ignores the result based on sense data.
>
> Can you check what happens with the horrible hack below:
>
> diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
> index 6f7128f49c30..2f384ddb001a 100644
> --- a/drivers/scsi/scsi_scan.c
> +++ b/drivers/scsi/scsi_scan.c
> @@ -603,7 +603,7 @@ static int scsi_probe_lun(struct scsi_device *sdev,
> unsigned char *inq_result,
> SCSI_LOG_SCAN_BUS(3, sdev_printk(KERN_INFO, sdev,
> "scsi scan: INQUIRY %s with code 0x%x\n",
> result ? "failed" : "successful", result));
> -
> +#if 0
> if (result) {
> /*
>* not-ready to ready transition [asc/ascq=0x28/0x0]
> @@ -628,6 +628,12 @@ static int scsi_probe_lun(struct scsi_device *sdev,
> unsigned char *inq_result,
> if (resid == try_inquiry_len)
> continue;
> }
> +#else
> + if (result) {
> + printk_ratelimited("got result %d:\n", result);
> + result = 0;
> + }
> +#endif
> break;
> }
>
I tried that hack and the printk never hit. Could be related to error being
masked
by storvsc driver workaround/hack.
Also let the system continue after going off in the weeds during SCSI scan.
After a long time we get stuck threads then EOM.
[ 182.444084] hv_storvsc: INQUIRY cmd 0x12 0x1 0x83 scsi status 0x0 srb status
0x1 length 52
[ 182.448080] hv_storvsc: payload size 288 count 1 offset 0 len 254 pfn
0x1e3683
[ 182.448080] hv_storvsc: sg 0: phys 0x1e3683000 virt 885b63683000 offset
0x0 length 254
[ 182.448080] data: : 00 83 00 30 01 01 00 18 4d 53 46 54 20 20 20 20
...0MSFT
[ 182.448080] data: 0010: 43 77 cc 85 5f 19 c2 46 ac 48 c7 33 b9 dd 2d 2a
Cw.._..F.H.3..-*
[ 182.448080] data: 0020: 01 03 00 10 60 02 24 80 43 77 cc 85 5f 19 c7 33
`.$.Cw.._..3
[ 182.448080] data: 0030: b9 dd 2d 2a 00 00 00 00 00 00 00 00 00 00 00 00
..-*
[ 182.448080] data: 0040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 0050: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 0060: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 0070: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 0080: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 0090: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 182.448080] data: 00f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00
..
[ 242.652032] INFO: task kworker/u480:0:5 blocked for more than 120 seconds.
[ 242.655042] Not tainted 4.10.0-next-20170228-next+ #4
[ 242.656647] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 242.659539] kworker/u480:0 D0 5 2 0x
[ 242.661100] Workqueue: events_unbound async_run_entry_fn
[ 242.663105] Call Trace:
[ 242.664209] __schedule+0x27a/0x890
[ 242.665179] schedule+0x36/0x80
[ 242.666520] io_schedule+0x16/0x40
[ 242.667933] do_read_cache_page+0x400/0x550
[ 242.669153] ? blkdev_writepages+0x40/0x40
[ 242.670775] ? page_cache_tree_insert+0x120/0x120
[ 242.672717] read_cache_page+0x12/0x20
[ 242.674592] read_dev_sector+0x7d/0xe0
[ 242.676457] ? get_page_from_freelist+0x891/0xad0
[ 242.679027] read_lba+0x193/0x270
[ 242.680421] ? kmem_cache_alloc_trace+0x181/0x190
[ 242.682573] efi_partition+0xf6/0x840
[ 242.684111] ? string+0x59/0x80
[ 242.685066] ? snprintf+0x49/0x60
[ 242.685904] ? compare_gpts+0x280/0x280
[ 242.688018] check_partition+0x13d/0x210
[ 242.689747] rescan_partitions+0xb8/0x370
[ 242.691810] ? get_device+0x17/0x20
[ 242.693415] ? down_write+0x12/0x40
[
Re: SCSI regression in 4.11
On Thu, Mar 02, 2017 at 01:01:35AM +0100, Christoph Hellwig wrote:
> On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> > >
> > > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
> >
> > It appears that is already in the code I am testing in linux-next...
>
> It's in -next now, but it wasn't at the time you reported the bug.
>
> And it would sortof explain the bug if the INQUIRY data is correct
> in the scatterlist, but we ignore it, given that scsi_probe_lun
> ignores the result based on sense data.
>
> Can you check what happens with the horrible hack below:
Strike that - we're checking result later, so this can't be the case.
Now the other interesting thing is the memset in __scsi_exectute,
which looks very suspicious. Try the following please:
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 3e32dc954c3c..22f4fb550561 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -253,7 +253,8 @@ static int __scsi_execute(struct scsi_device *sdev, const
unsigned char *cmd,
* and prevent security leaks by zeroing out the excess data.
*/
if (unlikely(rq->resid_len > 0 && rq->resid_len <= bufflen))
- memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
+// memset(buffer + (bufflen - rq->resid_len), 0, rq->resid_len);
+ printk_ratelimited("%s: got resid %d\n", __func__,
rq->resid_len);
if (resid)
*resid = rq->resid_len;
Re: SCSI regression in 4.11
On Wed, 2017-03-01 at 10:57 -0800, James Bottomley wrote: > On Wed, 2017-03-01 at 10:48 -0800, Stephen Hemminger wrote: > > On Tue, 28 Feb 2017 22:20:58 -0800 > > James Bottomley wrote: > > > > > On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > > > > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > > srb > > > > status 0x20 length 36 > > > > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff > > > > f0 > > > > 64 > > > > 02 89 ff ff ff ff > > > > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 > > > > 00 > > > > 00 > > > > 00 00 00 00 00 00 > > > > [1.359996] inquiry data: 0020: 00 00 00 00 > > > > [1.361835] scsi host1: scsi scan: INQUIRY result too short > > > > (5), > > > > using 36 > > > > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 > > > > srb > > > > status 0x1 length 16 > > > > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > > srb > > > > status 0x1 length 36 > > > > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff > > > > f0 > > > > 64 > > > > 02 89 ff ff ff ff > > > > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 > > > > 00 > > > > 00 > > > > 00 00 00 00 00 00 > > > > [1.362309] inquiry data: 0020: 00 00 00 00 > > > > [1.377423] scsi 1:0:0:1: Direct-Access > > > > > > > > > > > > PQ: 0 ANSI: 0 > > > > > > Well, this pinpoints the fault to the block uncopy, I think. The > > > Inquiry data is clearly correct in the page frame, so it's not > > > getting > > > copied to the scsi_execute() buffer for some reason. > > > > > > James > > > > > > > Why do I see different sense data on good (4.10) versus bad (4.11) > > > > Good 4.10 initial INQUIRY buffer > > [1.012413] data: : 00 2e 64 71 db 97 ff ff f0 94 62 96 > > ff > > ff ff ff > > [1.012413] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 > > 00 00 00 > > [1.012414] data: 0020: 00 00 00 00 > > > > Bad 4.11 initial INQUIRY buffer > > [1.218159] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 > > 20 > > 20 20 20 > > [1.225654] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b > > 20 > > 20 20 20 > > [1.242930] data: 0020: 31 2e 30 20 > > > > Is the kmap_atomic looking at the right place? > > Actually, the 4.11 data looks good. You can tell from the string at > byte 8. It's rubbish in the 4.10 one and 'Msft ' in the 4.11 one (I > assume you just reversed the cut and paste). > > These should be the page physical addresses you sent down to the > hypervisor, so kmap should work. Perhaps print out the physical page > address so we see what we're getting. Another possible explanation is non zero sg->offset, in which case you might not see the INQUIRY data because you start at the beginning of the page. This shouldn't happen because you specify no alignment override in the driver, so we should start the INQUIRY buffer on a new page and copy the data back to the real buffer, but perhaps that's what changed. James
Re: SCSI regression in 4.11
On Wed, 01 Mar 2017 15:09:44 -0800 James Bottomley wrote: > On Wed, 2017-03-01 at 13:27 -0800, Stephen Hemminger wrote: > > Ok here is much better data, wasn't accounting for the offset in the > > payload > > But now both responses are the same: > > > Working 4.10 > [...] > > [1.048920] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 > > srb status 0x20 length 36 > > [1.048920] hv_storvsc: payload size 288 count 1 offset 1024 len > > 36 pfn 0x1f15d7 > > [1.048921] hv_storvsc: sg 0: phys 0x1f15d7000 virt > > 9270b15d7000 offset 0x400 length 36 > > [1.048922] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 > > [1.048923] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 > > [1.048923] data: 0020: 00 00 00 00 > > > > [1.048942] scsi host1: scsi scan: INQUIRY result too short (5), > > using 36 > > > > > > Broken 4.11 > [...] > > [1.812926] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 > > srb status 0x20 length 36 > > [1.812927] hv_storvsc: payload size 288 count 1 offset 2816 len > > 36 pfn 0x1f198b > > [1.812928] hv_storvsc: sg 0: phys 0x1f198b000 virt > > 9a42f198b000 offset 0xb00 length 36 > > [1.812953] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 > > [1.812953] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 > > [1.812954] data: 0020: 00 00 00 00 > > > > [1.813258] scsi host1: scsi scan: INQUIRY result too short (5), > > using 36 > > Hyper-v is returning a buffer of zeros for INQUIRY to the offline > device in both cases ... that means the problem isn't where I thought > it was. > > James Yes. Earlier output wasn't accounting for offsets, new dump code is.
Re: SCSI regression in 4.11
On Wed, 2017-03-01 at 13:27 -0800, Stephen Hemminger wrote: > Ok here is much better data, wasn't accounting for the offset in the > payload But now both responses are the same: > Working 4.10 [...] > [1.048920] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 > srb status 0x20 length 36 > [1.048920] hv_storvsc: payload size 288 count 1 offset 1024 len > 36 pfn 0x1f15d7 > [1.048921] hv_storvsc: sg 0: phys 0x1f15d7000 virt > 9270b15d7000 offset 0x400 length 36 > [1.048922] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [1.048923] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [1.048923] data: 0020: 00 00 00 00 > > [1.048942] scsi host1: scsi scan: INQUIRY result too short (5), > using 36 > > > Broken 4.11 [...] > [1.812926] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 > srb status 0x20 length 36 > [1.812927] hv_storvsc: payload size 288 count 1 offset 2816 len > 36 pfn 0x1f198b > [1.812928] hv_storvsc: sg 0: phys 0x1f198b000 virt > 9a42f198b000 offset 0xb00 length 36 > [1.812953] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [1.812953] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [1.812954] data: 0020: 00 00 00 00 > > [1.813258] scsi host1: scsi scan: INQUIRY result too short (5), > using 36 Hyper-v is returning a buffer of zeros for INQUIRY to the offline device in both cases ... that means the problem isn't where I thought it was. James
Re: SCSI regression in 4.11
On Wed, Mar 01, 2017 at 07:54:12AM -0800, Stephen Hemminger wrote:
> >
> > http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
>
> It appears that is already in the code I am testing in linux-next...
It's in -next now, but it wasn't at the time you reported the bug.
And it would sortof explain the bug if the INQUIRY data is correct
in the scatterlist, but we ignore it, given that scsi_probe_lun
ignores the result based on sense data.
Can you check what happens with the horrible hack below:
diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
index 6f7128f49c30..2f384ddb001a 100644
--- a/drivers/scsi/scsi_scan.c
+++ b/drivers/scsi/scsi_scan.c
@@ -603,7 +603,7 @@ static int scsi_probe_lun(struct scsi_device *sdev,
unsigned char *inq_result,
SCSI_LOG_SCAN_BUS(3, sdev_printk(KERN_INFO, sdev,
"scsi scan: INQUIRY %s with code 0x%x\n",
result ? "failed" : "successful", result));
-
+#if 0
if (result) {
/*
* not-ready to ready transition [asc/ascq=0x28/0x0]
@@ -628,6 +628,12 @@ static int scsi_probe_lun(struct scsi_device *sdev,
unsigned char *inq_result,
if (resid == try_inquiry_len)
continue;
}
+#else
+ if (result) {
+ printk_ratelimited("got result %d:\n", result);
+ result = 0;
+ }
+#endif
break;
}
Re: SCSI regression in 4.11
On Wed, Mar 1, 2017 at 10:48 AM, Stephen Hemminger wrote: > > Bad 4.11 initial INQUIRY buffer > [1.218159] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 > [1.225654] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 > [1.242930] data: 0020: 31 2e 30 20 "MsftVirtual Disk1.0 ." in case anybody wondered about what the ascii data was, like I did. Linus
Re: SCSI regression in 4.11
Ok here is much better data, wasn't accounting for the offset in the payload Working 4.10 [1.020041] scsi host0: storvsc_host_t [1.024998] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1 length 36 [1.027452] hv_storvsc: payload size 288 count 1 offset 3072 len 36 pfn 0x1f15d0 [1.029385] hv_storvsc: sg 0: phys 0x1f15d virt 9270b15d offset 0xc00 length 36 [1.031720] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 Msft [1.033846] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 Virtual Disk [1.036080] data: 0020: 31 2e 30 20 1.0 [1.038249] scsi 0:0:0:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [1.040394] hv_storvsc: INQUIRY cmd 0x12 0x1 0x0 scsi status 0x0 srb status 0x1 length 12 [1.041494] scsi host1: storvsc_host_t [1.044683] hv_storvsc: payload size 288 count 1 offset 0 len 255 pfn 0x1f0faf [1.046940] hv_storvsc: sg 0: phys 0x1f0faf000 virt 9270b0faf000 offset 0x0 length 255 [1.048555] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1 length 36 [1.048556] hv_storvsc: payload size 288 count 1 offset 2816 len 36 pfn 0x1f15d6 [1.048557] hv_storvsc: sg 0: phys 0x1f15d6000 virt 9270b15d6000 offset 0xb00 length 36 [1.048559] data: : 05 80 00 02 1f 00 00 00 4d 73 66 74 20 20 20 20 Msft [1.048560] data: 0010: 56 69 72 74 75 61 6c 20 44 56 44 2d 52 4f 4d 20 Virtual DVD-ROM [1.048560] data: 0020: 31 2e 30 20 1.0 [1.048590] scsi 1:0:0:0: CD-ROMMsft Virtual DVD-ROM 1.0 PQ: 0 ANSI: 0 [1.048920] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20 length 36 [1.048920] hv_storvsc: payload size 288 count 1 offset 1024 len 36 pfn 0x1f15d7 [1.048921] hv_storvsc: sg 0: phys 0x1f15d7000 virt 9270b15d7000 offset 0x400 length 36 [1.048922] data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [1.048923] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [1.048923] data: 0020: 00 00 00 00 [1.048942] scsi host1: scsi scan: INQUIRY result too short (5), using 36 Broken 4.11 [1.487930] scsi host0: storvsc_host_t [1.541254] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1 length 36 [1.545242] hv_storvsc: payload size 288 count 1 offset 768 len 36 pfn 0x1f1196 [1.545242] hv_storvsc: sg 0: phys 0x1f1196000 virt 9a42f1196000 offset 0x300 length 36 [1.545242] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 Msft [1.545242] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 Virtual Disk [1.545242] data: 0020: 31 2e 30 20 1.0 [1.570136] scsi 0:0:0:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [1.571001] scsi host1: storvsc_host_t [1.608793] hv_storvsc: INQUIRY cmd 0x12 0x1 0x0 scsi status 0x0 srb status 0x1 length 12 [1.610316] hv_storvsc: payload size 288 count 1 offset 0 len 255 pfn 0x1f0577 [1.611749] hv_storvsc: sg 0: phys 0x1f0577000 virt 9a42f0577000 offset 0x0 length 255 [1.612788] data: : 00 00 00 08 00 83 8f b0 b1 b2 ce cf 72 65 61 74 reat [1.612788] data: 0010: 65 5f 66 69 6c 65 00 5f 5f 63 72 63 5f 68 69 64 e_file.__crc_hid [1.612788] data: 0020: 5f 72 65 70 6f 72 74 5f 72 61 77 5f 65 76 65 6e _report_raw_even [1.612788] data: 0030: 74 00 76 66 72 65 65 00 75 6e 72 65 67 69 73 74 t.vfree.unregist [1.612788] data: 0040: 65 72 5f 63 68 72 64 65 76 5f 72 65 67 69 6f 6e er_chrdev_region [1.612788] data: 0050: 00 6d 75 74 65 78 5f 75 6e 6c 6f 63 6b 00 68 69 .mutex_unlock.hi [1.612788] data: 0060: 64 5f 64 65 62 75 67 5f 65 78 69 74 00 6b 6d 65 d_debug_exit.kme [1.612788] data: 0070: 6d 64 75 70 00 68 69 64 72 61 77 5f 65 78 69 74 mdup.hidraw_exit [1.612788] data: 0080: 00 5f 5f 67 65 74 5f 75 73 65 72 5f 34 00 70 6f .__get_user_4.po [1.612788] data: 0090: 77 65 72 5f 73 75 70 70 6c 79 5f 70 6f 77 65 72 wer_supply_power [1.612788] data: 00a0: 73 00 64 65 76 69 63 65 5f 64 65 73 74 72 6f 79 s.device_destroy [1.612788] data: 00b0: 00 5f 5f 63 72 63 5f 68 69 64 5f 73 6e 74 6f 33 .__crc_hid_snto3 [1.612788] data: 00c0: 32 00 63 61 6e 63 65 6c 5f 77 6f 72 6b 5f 73 79 2.cancel_work_sy [1.612788] data: 00d0: 6e 63 00 73 65 71 5f 70 72 69 6e 74 66 00 64 6f nc.seq_printf.do [1.612788] data: 00e0: 77 6e 5f 69 6e 74 65 72 72 75 70 74 69 62 6c 65 wn_interruptible [1.612788] data: 00f0: 00 5f 5f 63 72 63 5f 68 69 64 5f 70 61 72 73 .__crc_hid_pars [1.649097] hv
Re: SCSI regression in 4.11
On Wed, 01 Mar 2017 11:20:22 -0800 James Bottomley wrote: > On Wed, 2017-03-01 at 10:57 -0800, James Bottomley wrote: > > On Wed, 2017-03-01 at 10:48 -0800, Stephen Hemminger wrote: > > > On Tue, 28 Feb 2017 22:20:58 -0800 > > > James Bottomley wrote: > > > > > > > On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > > > > > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > > > srb > > > > > status 0x20 length 36 > > > > > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff > > > > > f0 > > > > > 64 > > > > > 02 89 ff ff ff ff > > > > > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 > > > > > 00 > > > > > 00 > > > > > 00 00 00 00 00 00 > > > > > [1.359996] inquiry data: 0020: 00 00 00 00 > > > > > [1.361835] scsi host1: scsi scan: INQUIRY result too short > > > > > (5), > > > > > using 36 > > > > > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 > > > > > srb > > > > > status 0x1 length 16 > > > > > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > > > srb > > > > > status 0x1 length 36 > > > > > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff > > > > > f0 > > > > > 64 > > > > > 02 89 ff ff ff ff > > > > > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 > > > > > 00 > > > > > 00 > > > > > 00 00 00 00 00 00 > > > > > [1.362309] inquiry data: 0020: 00 00 00 00 > > > > > [1.377423] scsi 1:0:0:1: Direct-Access > > > > > > > > > > > > > > > PQ: 0 ANSI: 0 > > > > > > > > Well, this pinpoints the fault to the block uncopy, I think. The > > > > Inquiry data is clearly correct in the page frame, so it's not > > > > getting > > > > copied to the scsi_execute() buffer for some reason. > > > > > > > > James > > > > > > > > > > Why do I see different sense data on good (4.10) versus bad (4.11) > > > > > > Good 4.10 initial INQUIRY buffer > > > [1.012413] data: : 00 2e 64 71 db 97 ff ff f0 94 62 96 > > > ff > > > ff ff ff > > > [1.012413] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 > > > [1.012414] data: 0020: 00 00 00 00 > > > > > > Bad 4.11 initial INQUIRY buffer > > > [1.218159] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 > > > 20 > > > 20 20 20 > > > [1.225654] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b > > > 20 > > > 20 20 20 > > > [1.242930] data: 0020: 31 2e 30 20 > > > > > > Is the kmap_atomic looking at the right place? > > > > Actually, the 4.11 data looks good. You can tell from the string at > > byte 8. It's rubbish in the 4.10 one and 'Msft ' in the 4.11 one (I > > assume you just reversed the cut and paste). > > > > These should be the page physical addresses you sent down to the > > hypervisor, so kmap should work. Perhaps print out the physical page > > address so we see what we're getting. > > Another possible explanation is non zero sg->offset, in which case you > might not see the INQUIRY data because you start at the beginning of > the page. This shouldn't happen because you specify no alignment > override in the driver, so we should start the INQUIRY buffer on a new > page and copy the data back to the real buffer, but perhaps that's what > changed. Dumping more data from 4.9, 4.10 and 4.11
Re: SCSI regression in 4.11
On Wed, 2017-03-01 at 10:48 -0800, Stephen Hemminger wrote: > On Tue, 28 Feb 2017 22:20:58 -0800 > James Bottomley wrote: > > > On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > > > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > srb > > > status 0x20 length 36 > > > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff f0 > > > 64 > > > 02 89 ff ff ff ff > > > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 00 00 00 > > > [1.359996] inquiry data: 0020: 00 00 00 00 > > > [1.361835] scsi host1: scsi scan: INQUIRY result too short > > > (5), > > > using 36 > > > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 > > > srb > > > status 0x1 length 16 > > > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 > > > srb > > > status 0x1 length 36 > > > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 > > > 64 > > > 02 89 ff ff ff ff > > > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 00 00 00 > > > [1.362309] inquiry data: 0020: 00 00 00 00 > > > [1.377423] scsi 1:0:0:1: Direct-Access > > > > > > PQ: 0 ANSI: 0 > > > > Well, this pinpoints the fault to the block uncopy, I think. The > > Inquiry data is clearly correct in the page frame, so it's not > > getting > > copied to the scsi_execute() buffer for some reason. > > > > James > > > > Why do I see different sense data on good (4.10) versus bad (4.11) > > Good 4.10 initial INQUIRY buffer > [1.012413] data: : 00 2e 64 71 db 97 ff ff f0 94 62 96 ff > ff ff ff > [1.012413] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [1.012414] data: 0020: 00 00 00 00 > > Bad 4.11 initial INQUIRY buffer > [1.218159] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 20 > 20 20 20 > [1.225654] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 > 20 20 20 > [1.242930] data: 0020: 31 2e 30 20 > > Is the kmap_atomic looking at the right place? Actually, the 4.11 data looks good. You can tell from the string at byte 8. It's rubbish in the 4.10 one and 'Msft ' in the 4.11 one (I assume you just reversed the cut and paste). These should be the page physical addresses you sent down to the hypervisor, so kmap should work. Perhaps print out the physical page address so we see what we're getting. James
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 22:20:58 -0800 James Bottomley wrote: > On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > > status 0x20 length 36 > > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [1.359996] inquiry data: 0020: 00 00 00 00 > > [1.361835] scsi host1: scsi scan: INQUIRY result too short (5), > > using 36 > > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 srb > > status 0x1 length 16 > > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > > status 0x1 length 36 > > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [1.362309] inquiry data: 0020: 00 00 00 00 > > [1.377423] scsi 1:0:0:1: Direct-Access > > PQ: 0 ANSI: 0 > > Well, this pinpoints the fault to the block uncopy, I think. The > Inquiry data is clearly correct in the page frame, so it's not getting > copied to the scsi_execute() buffer for some reason. > > James > Why do I see different sense data on good (4.10) versus bad (4.11) Good 4.10 initial INQUIRY buffer [1.012413] data: : 00 2e 64 71 db 97 ff ff f0 94 62 96 ff ff ff ff [1.012413] data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [1.012414] data: 0020: 00 00 00 00 Bad 4.11 initial INQUIRY buffer [1.218159] data: : 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 [1.225654] data: 0010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 [1.242930] data: 0020: 31 2e 30 20 Is the kmap_atomic looking at the right place?
Re: SCSI regression in 4.11
Dexuan has reproduced the same problem and discovered that is related to whether virtual DVD is attached to the VM. My VM had empty virtual DVD (offline) from the installation of the ISO. If the DVD device is removed then the VM boots. This makes the problem less of a catastrophic but we still need to get to root cause.
Re: SCSI regression in 4.11
On Tue, Feb 28, 2017 at 10:48:45PM -0800, Stephen Hemminger wrote: > Let me know, I can run another test and dump more data. Could it be that we keep the old sense buffer values around because my commit change the way how sense buffers are handled. A while ago I suggested this patch to fix it, so maybe you can try it: http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
Re: SCSI regression in 4.11
On Wed, 1 Mar 2017 16:50:57 +0100
Christoph Hellwig wrote:
> On Tue, Feb 28, 2017 at 10:48:45PM -0800, Stephen Hemminger wrote:
> > Let me know, I can run another test and dump more data.
>
> Could it be that we keep the old sense buffer values around because
> my commit change the way how sense buffers are handled. A while ago
> I suggested this patch to fix it, so maybe you can try it:
>
>
> http://git.infradead.org/users/hch/block.git/commitdiff/148cff67b401e2229c076c0ea418712654be77e4
It appears that is already in the code I am testing in linux-next...
bool scsi_normalize_sense(const u8 *sense_buffer, int sb_len,
struct scsi_sense_hdr *sshdr)
{
memset(sshdr, 0, sizeof(struct scsi_sense_hdr));
if (!sense_buffer || !sb_len)
return false;
sshdr->response_code = (sense_buffer[0] & 0x7f);
if (!scsi_sense_valid(sshdr))
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 22:20:58 -0800 James Bottomley wrote: > On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > > status 0x20 length 36 > > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [1.359996] inquiry data: 0020: 00 00 00 00 > > [1.361835] scsi host1: scsi scan: INQUIRY result too short (5), > > using 36 > > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 srb > > status 0x1 length 16 > > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > > status 0x1 length 36 > > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [1.362309] inquiry data: 0020: 00 00 00 00 > > [1.377423] scsi 1:0:0:1: Direct-Access > > PQ: 0 ANSI: 0 > > Well, this pinpoints the fault to the block uncopy, I think. The > Inquiry data is clearly correct in the page frame, so it's not getting > copied to the scsi_execute() buffer for some reason. > > James > Let me know, I can run another test and dump more data.
Re: SCSI regression in 4.11
On Tue, 2017-02-28 at 17:25 -0800, Stephen Hemminger wrote: > [1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > status 0x20 length 36 > [1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff f0 64 > 02 89 ff ff ff ff > [1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > 00 00 00 00 00 00 > [1.359996] inquiry data: 0020: 00 00 00 00 > [1.361835] scsi host1: scsi scan: INQUIRY result too short (5), > using 36 > [1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 srb > status 0x1 length 16 > [1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > status 0x1 length 36 > [1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 64 > 02 89 ff ff ff ff > [1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 > 00 00 00 00 00 00 > [1.362309] inquiry data: 0020: 00 00 00 00 > [1.377423] scsi 1:0:0:1: Direct-Access > PQ: 0 ANSI: 0 Well, this pinpoints the fault to the block uncopy, I think. The Inquiry data is clearly correct in the page frame, so it's not getting copied to the scsi_execute() buffer for some reason. James
Re: SCSI regression in 4.11
On Tue, 2017-02-28 at 10:41 -0800, Stephen Hemminger wrote: > [1.652279] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb > status 0x20 length 36 > [1.652297] scsi host1: scsi scan: INQUIRY result too short (5), > using 36 This is definitive. We sent the Inquiry command, we got 36 bytes of payload from hyperv (correct size), but when we tried to get the length from the data buffer of the command, we found zeros where it should have been (the length is the byte at offset 4 plus 5). Wherever the inquiry data went it wasn't into the command buffer ... it's like we have some type of sg list setup error, but I can't find it. James
Re: SCSI regression in 4.11
On Tue, 2017-02-28 at 10:57 -0800, Stephen Hemminger wrote:
> On Tue, 28 Feb 2017 09:06:13 -0800
> James Bottomley wrote:
>
> > On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
> > > On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> > > > On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger
> > > > wrote:
> > > > > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before
> > > > > each
> > > > > I/O")
> > > > >
> > > > > but that is already in linux-next.
> > > > >
> > > > > Noticed another place where memset(of the data was being done
> > > > > not
> > > > > the extra bits.
> > > > > Tried this, but didn't fix it either...
> > > >
> > > > Are you using blk-mq or the legacy request code?
> > >
> > > Stephen doesn't have MQ set in the config he posted, I'm assuming
> > > he
> > > didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
> > > asked if turning on MQ makes a difference.
> >
> > OK, since we're not making much progress, Stephen, could you insert
> > some debugging into the storvsc driver? The trace clearly shows
> > we're
> > getting zeros back in the buffer when we should have data from the
> > initial scan. Firstly, does the vmbus think it's transferring any
> > data
> > for the INQUIRY and READ_CAPACITY commands (looks like
> > storvsc_command_completion() data_transfer_length)? If it does,
> > there's probably an issue initialising the sg list. If it doesn't,
> > we're probably sending bogus commands.
> >
> > James
> >
>
> The following code in storvsc looks suspicious
>
> static void storvsc_on_io_completion(struct storvsc_device
> *stor_device,
> struct vstor_packet *vstor_packet,
> struct storvsc_cmd_request *request)
> {
> struct vstor_packet *stor_pkt;
> struct hv_device *device = stor_device->device;
>
> stor_pkt = &request->vstor_packet;
>
> /*
>* The current SCSI handling on the host side does
>* not correctly handle:
>* INQUIRY command with page code parameter set to 0x80
>* MODE_SENSE command with cmd[2] == 0x1c
>*
>* Setup srb and scsi status so this won't be fatal.
>* We do this so we can distinguish truly fatal failues
>* (srb status == 0x4) and off-line the device in that case.
>*/
>
> if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
> (stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
> vstor_packet->vm_srb.scsi_status = 0;
> vstor_packet->vm_srb.srb_status = SRB_STATUS_SUCCESS;
> }
>
> If SCSI layer is sending inquiry about devices to do scanning then
> wouldn't this workaround break things? Maybe a better to fully test
> for the broken command.
Let's concentrate on INQUIRY since that's the first command in the
probe sequence. I think it's completing successfully because your
hyperv layer says it has 36 bytes of transfer and that's the size of a
successful initial INQUIRY, so the fact that the code above would break
stuff if the INQUIRY failed is orthogonal to the the current problem.
can you print out some of the DMA buffer in storvsc_on_io_completion()?
I think just the stor_pkt->vm_srb.cdb[0] (to identify the command
completing) and byte 5 of the buffer will tell us what we need to know.
It's going to be complex to get byte 5, you'll need to do a
kmap_atomic_pfn on request->payload->range.pfn_array[0] and then look
at byte 5. If that's zero it means there's some problem with hyperv
writing to the pfn if it's 0x24 (expected value for an initial inquiry)
we've got a problem somewhere in bio completion not copying the value
back.
James
Re: SCSI regression in 4.11
> Let's concentrate on INQUIRY since that's the first command in the
> probe sequence. I think it's completing successfully because your
> hyperv layer says it has 36 bytes of transfer and that's the size of a
> successful initial INQUIRY, so the fact that the code above would break
> stuff if the INQUIRY failed is orthogonal to the the current problem.
Right, that bodge only breaks some minor things likes scsiinfo commands.
> can you print out some of the DMA buffer in storvsc_on_io_completion()?
>
> I think just the stor_pkt->vm_srb.cdb[0] (to identify the command
> completing) and byte 5 of the buffer will tell us what we need to know.
> It's going to be complex to get byte 5, you'll need to do a
> kmap_atomic_pfn on request->payload->range.pfn_array[0] and then look
> at byte 5. If that's zero it means there's some problem with hyperv
> writing to the pfn if it's 0x24 (expected value for an initial inquiry)
> we've got a problem somewhere in bio completion not copying the value
> back.
Here is another boot, this time went dumpster diving as you suggested
to get the request data.
diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
index 2af63a80c7fa..a51d8eba6e04 100644
--- a/drivers/scsi/storvsc_drv.c
+++ b/drivers/scsi/storvsc_drv.c
@@ -1059,6 +1059,21 @@ static void storvsc_on_io_completion(struct
storvsc_device *stor_device,
vstor_packet->vm_srb.srb_status,
vstor_packet->vm_srb.data_transfer_length);
+ if (stor_pkt->vm_srb.cdb[0] == INQUIRY) {
+ struct scsi_cmnd *cmd = request->cmd;
+ struct scatterlist *sg = scsi_sglist(cmd);
+ struct page *page = sg_page(sg);
+ void *vaddr = kmap_atomic(page);
+
+ print_hex_dump(KERN_INFO,
+ "inquiry data: ", DUMP_PREFIX_OFFSET,
+ 16, 1,
+ vaddr, vstor_packet->vm_srb.data_transfer_length,
+ false);
+
+ kunmap_atomic(page);
+ }
+
/*
* The current SCSI handling on the host side does
* not correctly handle:
Which results in:
...
[1.225501] scsi host0: storvsc_host_t
[1.234707] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1
length 36
[1.235517] scsi host1: storvsc_host_t
[1.238037] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 64 02 89 ff
ff ff ff
[1.256800] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
[1.259430] inquiry data: 0020: 00 00 00 00
[1.261431] scsi 0:0:0:0: Direct-Access Msft Virtual Disk 1.0
PQ: 0 ANSI: 5
[1.264080] hv_storvsc: IO cmd 0x12 0x1 0x0 scsi status 0x0 srb status 0x1
length 12
[1.267420] inquiry data: : 00 00 00 08 00 83 8f b0 b1 b2 ce cf
[1.270759] hv_storvsc: IO cmd 0x12 0x1 0x83 scsi status 0x0 srb status 0x1
length 52
[1.275007] inquiry data: : 00 83 00 30 01 01 00 18 4d 53 46 54 20
20 20 20
[1.277988] inquiry data: 0010: 43 77 cc 85 5f 19 c2 46 ac 48 c7 33 b9
dd 2d 2a
[1.281096] inquiry data: 0020: 01 03 00 10 60 02 24 80 43 77 cc 85 5f
19 c7 33
[1.284246] inquiry data: 0030: b9 dd 2d 2a
[1.306538] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1
length 36
[1.310621] inquiry data: : 00 92 be f1 5c 98 ff ff f0 64 02 89 ff
ff ff ff
[1.316244] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
[1.328151] random: fast init done
[1.340184] inquiry data: 0020: 00 00 00 00
[1.342710] scsi 1:0:0:0: CD-ROMMsft Virtual DVD-ROM 1.0
PQ: 0 ANSI: 0
[1.346023] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.352913] inquiry data: : 00 aa be f1 5c 98 ff ff f0 64 02 89 ff
ff ff ff
[1.356543] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
[1.359996] inquiry data: 0020: 00 00 00 00
[1.361835] scsi host1: scsi scan: INQUIRY result too short (5), using 36
[1.361888] hv_storvsc: IO cmd 0xa0 0x0 0x0 scsi status 0x0 srb status 0x1
length 16
[1.362307] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1
length 36
[1.362308] inquiry data: : 00 23 34 f1 5c 98 ff ff f0 64 02 89 ff
ff ff ff
[1.362309] inquiry data: 0010: 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
[1.362309] inquiry data: 0020: 00 00 00 00
[1.377423] scsi 1:0:0:1: Direct-Access
PQ: 0 ANSI: 0
[1.399208] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.402836] inquiry data: : 00 a3 be f1 5c 98 ff ff 00 00 00 00 00
00 00 00
[1.406466] inquiry data: 0010: 00 00 00 00 00 00 00 00 c0 30 66 f9 5c
98 ff ff
[1.409766] inquiry data: 0020: 00 00 00 00
[1.412366] scsi 1:0:0:2: Direct-Access
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 09:06:13 -0800
James Bottomley wrote:
> On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
> > On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> > > On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> > > > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each
> > > > I/O")
> > > >
> > > > but that is already in linux-next.
> > > >
> > > > Noticed another place where memset(of the data was being done not
> > > > the extra bits.
> > > > Tried this, but didn't fix it either...
> > >
> > > Are you using blk-mq or the legacy request code?
> >
> > Stephen doesn't have MQ set in the config he posted, I'm assuming he
> > didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
> > asked if turning on MQ makes a difference.
>
> OK, since we're not making much progress, Stephen, could you insert
> some debugging into the storvsc driver? The trace clearly shows we're
> getting zeros back in the buffer when we should have data from the
> initial scan. Firstly, does the vmbus think it's transferring any data
> for the INQUIRY and READ_CAPACITY commands (looks like
> storvsc_command_completion() data_transfer_length)? If it does,
> there's probably an issue initialising the sg list. If it doesn't,
> we're probably sending bogus commands.
>
> James
I tried booting with scsi_mod.use_blk_mq=true and that did nothing.
Rebuilding now with
CONFIG_SCSI_MQ_DEFAULT=y
Sure, can instrument. after that test.
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 09:06:13 -0800
James Bottomley wrote:
> On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
> > On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> > > On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> > > > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each
> > > > I/O")
> > > >
> > > > but that is already in linux-next.
> > > >
> > > > Noticed another place where memset(of the data was being done not
> > > > the extra bits.
> > > > Tried this, but didn't fix it either...
> > >
> > > Are you using blk-mq or the legacy request code?
> >
> > Stephen doesn't have MQ set in the config he posted, I'm assuming he
> > didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
> > asked if turning on MQ makes a difference.
>
> OK, since we're not making much progress, Stephen, could you insert
> some debugging into the storvsc driver? The trace clearly shows we're
> getting zeros back in the buffer when we should have data from the
> initial scan. Firstly, does the vmbus think it's transferring any data
> for the INQUIRY and READ_CAPACITY commands (looks like
> storvsc_command_completion() data_transfer_length)? If it does,
> there's probably an issue initialising the sg list. If it doesn't,
> we're probably sending bogus commands.
>
> James
>
The following code in storvsc looks suspicious
static void storvsc_on_io_completion(struct storvsc_device *stor_device,
struct vstor_packet *vstor_packet,
struct storvsc_cmd_request *request)
{
struct vstor_packet *stor_pkt;
struct hv_device *device = stor_device->device;
stor_pkt = &request->vstor_packet;
/*
* The current SCSI handling on the host side does
* not correctly handle:
* INQUIRY command with page code parameter set to 0x80
* MODE_SENSE command with cmd[2] == 0x1c
*
* Setup srb and scsi status so this won't be fatal.
* We do this so we can distinguish truly fatal failues
* (srb status == 0x4) and off-line the device in that case.
*/
if ((stor_pkt->vm_srb.cdb[0] == INQUIRY) ||
(stor_pkt->vm_srb.cdb[0] == MODE_SENSE)) {
vstor_packet->vm_srb.scsi_status = 0;
vstor_packet->vm_srb.srb_status = SRB_STATUS_SUCCESS;
}
If SCSI layer is sending inquiry about devices to do scanning then wouldn't this
workaround break things? Maybe a better to fully test for the broken command.
Original commit was:
commit 4ed51a21c0f69e1379cf858fc21a9d9022bfe0e7
Author: K. Y. Srinivasan
Date: Sat Aug 27 11:31:26 2011 -0700
Staging: hv: storvsc: Fixup srb and scsi status for INQUIRY and MODE_SENSE
The current VHD handler on the Windows Host does not correctly handle
INQUIRY and MODE_SENSE commands with some options. Fixup srb_status
in these cases since the failure is not fatal.
Signed-off-by: K. Y. Srinivasan
Signed-off-by: Haiyang Zhang
Signed-off-by: Greg Kroah-Hartman
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 09:06:13 -0800
James Bottomley wrote:
> On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
> > On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> > > On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> > > > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each
> > > > I/O")
> > > >
> > > > but that is already in linux-next.
> > > >
> > > > Noticed another place where memset(of the data was being done not
> > > > the extra bits.
> > > > Tried this, but didn't fix it either...
> > >
> > > Are you using blk-mq or the legacy request code?
> >
> > Stephen doesn't have MQ set in the config he posted, I'm assuming he
> > didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
> > asked if turning on MQ makes a difference.
>
> OK, since we're not making much progress, Stephen, could you insert
> some debugging into the storvsc driver? The trace clearly shows we're
> getting zeros back in the buffer when we should have data from the
> initial scan. Firstly, does the vmbus think it's transferring any data
> for the INQUIRY and READ_CAPACITY commands (looks like
> storvsc_command_completion() data_transfer_length)? If it does,
> there's probably an issue initialising the sg list. If it doesn't,
> we're probably sending bogus commands.
>
> James
>
This is log of failed boot of linux-next (with blk_mq enabled).
See attached if you want to see exactly what got added.
Sorry don't speak SCSI yet.
[1.496999] hv_utils: Registering HyperV Utility Driver
[1.505415] hv_vmbus: registering driver hv_util
[1.508074] input: AT Translated Set 2 keyboard as
/devices/LNXSYSTM:00/LNXSYBUS:00/ACPI0004:00/VMBUS:00/d34b2567-b9b6-42b9-8778-0a4ec0b955bf/serio0/input/input0
[1.524314] hv_vmbus: registering driver hid_hyperv
[1.543577] hv_storvsc f71e9b3b-aed9-4dd2-a1ff-c00218a39853: complete init
request
[1.547120] hv_storvsc f71e9b3b-aed9-4dd2-a1ff-c00218a39853: complete init
request
[1.549952] hv_storvsc f71e9b3b-aed9-4dd2-a1ff-c00218a39853: complete init
request
[1.552876] hv_storvsc f71e9b3b-aed9-4dd2-a1ff-c00218a39853: complete init
request
[1.555931] hv_storvsc f71e9b3b-aed9-4dd2-a1ff-c00218a39853: complete init
request
[1.559151] scsi host0: storvsc_host_t
[1.590197] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1
length 36
[1.590765] hv_storvsc e7d171c1-a71d-400e-854e-7e0cc000ce3d: complete init
request
[1.590796] hv_storvsc e7d171c1-a71d-400e-854e-7e0cc000ce3d: complete init
request
[1.590820] hv_storvsc e7d171c1-a71d-400e-854e-7e0cc000ce3d: complete init
request
[1.590839] hv_storvsc e7d171c1-a71d-400e-854e-7e0cc000ce3d: complete init
request
[1.590942] hv_storvsc e7d171c1-a71d-400e-854e-7e0cc000ce3d: complete init
request
[1.591506] scsi host1: storvsc_host_t
[1.600925] hv_utils: Heartbeat IC version 3.0
[1.619450] input: Microsoft Vmbus HID-compliant Mouse as
/devices/0006:045E:0621.0001/input/input1
[1.620658] hid 0006:045E:0621.0001: input: HID v0.01 Mouse
[Microsoft Vmbus HID-compliant Mouse] on
[1.627185] hv_utils: Shutdown IC version 3.0
[1.627280] hv_utils: cannot register PTP clock: 0
[1.628081] random: fast init done
[1.628890] hv_utils: TimeSync IC version 4.0
[1.629407] hv_utils: VSS IC version 5.0
[1.651620] scsi 0:0:0:0: Direct-Access Msft Virtual Disk 1.0
PQ: 0 ANSI: 5
[1.651956] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1
length 36
[1.651977] scsi 1:0:0:0: CD-ROMMsft Virtual DVD-ROM 1.0
PQ: 0 ANSI: 0
[1.652279] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.652297] scsi host1: scsi scan: INQUIRY result too short (5), using 36
[1.652299] scsi 1:0:0:1: Direct-Access
PQ: 0 ANSI: 0
[1.652595] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.652611] scsi 1:0:0:2: Direct-Access
PQ: 0 ANSI: 0
[1.652892] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.652910] scsi 1:0:0:3: Direct-Access
PQ: 0 ANSI: 0
[1.653178] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.653195] scsi 1:0:0:4: Direct-Access
PQ: 0 ANSI: 0
[1.653445] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.653464] scsi 1:0:0:5: Direct-Access
PQ: 0 ANSI: 0
[1.653729] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.653746] scsi 1:0:0:6: Direct-Access
PQ: 0 ANSI: 0
[1.669879] hv_storvsc: IO cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20
length 36
[1.670143] scsi 1:0:0:7: Direct-Access
PQ: 0 A
Re: SCSI regression in 4.11
On 02/28/2017 10:16 AM, Stephen Hemminger wrote:
> On Tue, 28 Feb 2017 09:06:13 -0800
> James Bottomley wrote:
>
>> On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
>>> On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each
> I/O")
>
> but that is already in linux-next.
>
> Noticed another place where memset(of the data was being done not
> the extra bits.
> Tried this, but didn't fix it either...
Are you using blk-mq or the legacy request code?
>>>
>>> Stephen doesn't have MQ set in the config he posted, I'm assuming he
>>> didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
>>> asked if turning on MQ makes a difference.
>>
>> OK, since we're not making much progress, Stephen, could you insert
>> some debugging into the storvsc driver? The trace clearly shows we're
>> getting zeros back in the buffer when we should have data from the
>> initial scan. Firstly, does the vmbus think it's transferring any data
>> for the INQUIRY and READ_CAPACITY commands (looks like
>> storvsc_command_completion() data_transfer_length)? If it does,
>> there's probably an issue initialising the sg list. If it doesn't,
>> we're probably sending bogus commands.
>>
>> James
>
> I tried booting with scsi_mod.use_blk_mq=true and that did nothing.
> Rebuilding now with
> CONFIG_SCSI_MQ_DEFAULT=y
If you already booted with scsi_mod.use_blk_mq=true and tested that,
then don't bother with the config option. They basically toggle
the same switch.
> Sure, can instrument. after that test.
That'd be great!
--
Jens Axboe
Re: SCSI regression in 4.11
On Tue, 28 Feb 2017 15:08:12 +0100
Christoph Hellwig wrote:
> On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each I/O")
> >
> > but that is already in linux-next.
> >
> > Noticed another place where memset(of the data was being done not the extra
> > bits.
> > Tried this, but didn't fix it either...
>
> Are you using blk-mq or the legacy request code?
I was using legacy, but even with CONFIG_SCSI_MQ_DEFAULT=y
the same failure occurs.
Re: SCSI regression in 4.11
On Tue, 2017-02-28 at 08:32 -0700, Jens Axboe wrote:
> On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> > On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> > > Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each
> > > I/O")
> > >
> > > but that is already in linux-next.
> > >
> > > Noticed another place where memset(of the data was being done not
> > > the extra bits.
> > > Tried this, but didn't fix it either...
> >
> > Are you using blk-mq or the legacy request code?
>
> Stephen doesn't have MQ set in the config he posted, I'm assuming he
> didn't boot with scsi_mod.use_blk_mq=true. In a previous email, I
> asked if turning on MQ makes a difference.
OK, since we're not making much progress, Stephen, could you insert
some debugging into the storvsc driver? The trace clearly shows we're
getting zeros back in the buffer when we should have data from the
initial scan. Firstly, does the vmbus think it's transferring any data
for the INQUIRY and READ_CAPACITY commands (looks like
storvsc_command_completion() data_transfer_length)? If it does,
there's probably an issue initialising the sg list. If it doesn't,
we're probably sending bogus commands.
James
Re: SCSI regression in 4.11
On 02/28/2017 07:08 AM, Christoph Hellwig wrote:
> On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
>> Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each I/O")
>>
>> but that is already in linux-next.
>>
>> Noticed another place where memset(of the data was being done not the extra
>> bits.
>> Tried this, but didn't fix it either...
>
> Are you using blk-mq or the legacy request code?
Stephen doesn't have MQ set in the config he posted, I'm assuming he didn't
boot with scsi_mod.use_blk_mq=true. In a previous email, I asked if turning
on MQ makes a difference.
--
Jens Axboe
Re: SCSI regression in 4.11
On Mon, Feb 27, 2017 at 05:19:31PM -0800, Stephen Hemminger wrote:
> Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each I/O")
>
> but that is already in linux-next.
>
> Noticed another place where memset(of the data was being done not the extra
> bits.
> Tried this, but didn't fix it either...
Are you using blk-mq or the legacy request code?
Re: SCSI regression in 4.11
On 02/27/2017 06:19 PM, Stephen Hemminger wrote:
> On Mon, 27 Feb 2017 15:30:30 -0800
> Stephen Hemminger wrote:
>
>> Something in SCSI in 4.11 broke booting on Hyper-V Generation 2 VM with 8
>> VCPU and 4G of memory.
>> Both Linus's current tree (4.11 pre-rc1) and linux-next fail in a similar
>> manner. It looks like some error
>> in SCSI device detection because there is only a single device.
>>
>> The offending commit causing the regression is:
>>
>> $ git bisect bad
>> e9c787e65c0c36529745be47d490d998b4b6e589 is the first bad commit
>> commit e9c787e65c0c36529745be47d490d998b4b6e589
>> Author: Christoph Hellwig
>> Date: Mon Jan 2 21:55:26 2017 +0300
>>
>> scsi: allocate scsi_cmnd structures as part of struct request
>>
>> Rely on the new block layer functionality to allocate additional driver
>> specific data behind struct request instead of implementing it in SCSI
>> itѕelf.
>>
>> Signed-off-by: Christoph Hellwig
>> Acked-by: Martin K. Petersen
>> Reviewed-by: Hannes Reinecke
>> Signed-off-by: Jens Axboe
>>
>> :04 04 6ff016fcdae227efeb19c1c301b17ccd7ea35da6
>> 70d79f99d9b79ecf4dccbe067fc697219f5c78da M drivers
>> :04 04 a672ff52df8b2c211b3f98cae4a88d8a96ccde0b
>> 1aaaed7de0994f597c7f8290c722a0b4a7789429 M include
>>
>> I checked and tree is current and up to date and includes
>> commit ee5242360424b9b967454e9183767323d10cf985
>> Author: Christoph Hellwig
>> Date: Tue Feb 21 10:04:55 2017 +0100
>>
>> scsi: zero per-cmd driver data before each I/O
>>
>> Kernel config is attached. It started with Ubuntu config, but then did
>> localmodconfig and pruned
>> out unnecessary stuff.
>>
>
> This problem I am seeing looks like the one addressed by:
>
> Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each I/O")
>
> but that is already in linux-next.
>
> Noticed another place where memset(of the data was being done not the extra
> bits.
> Tried this, but didn't fix it either...
Yeah, that fix is already in Linus's tree. But it does look like a replica of
what Dexuan reported. Out of curiosity, does it boot if you enable
CONFIG_SCSI_MQ_DEFAULT?
Christoph, looks like the previous fix wasn't complete...
--
Jens Axboe
Re: SCSI regression in 4.11
On Mon, 27 Feb 2017 15:30:30 -0800
Stephen Hemminger wrote:
> Something in SCSI in 4.11 broke booting on Hyper-V Generation 2 VM with 8
> VCPU and 4G of memory.
> Both Linus's current tree (4.11 pre-rc1) and linux-next fail in a similar
> manner. It looks like some error
> in SCSI device detection because there is only a single device.
>
> The offending commit causing the regression is:
>
> $ git bisect bad
> e9c787e65c0c36529745be47d490d998b4b6e589 is the first bad commit
> commit e9c787e65c0c36529745be47d490d998b4b6e589
> Author: Christoph Hellwig
> Date: Mon Jan 2 21:55:26 2017 +0300
>
> scsi: allocate scsi_cmnd structures as part of struct request
>
> Rely on the new block layer functionality to allocate additional driver
> specific data behind struct request instead of implementing it in SCSI
> itѕelf.
>
> Signed-off-by: Christoph Hellwig
> Acked-by: Martin K. Petersen
> Reviewed-by: Hannes Reinecke
> Signed-off-by: Jens Axboe
>
> :04 04 6ff016fcdae227efeb19c1c301b17ccd7ea35da6
> 70d79f99d9b79ecf4dccbe067fc697219f5c78da Mdrivers
> :04 04 a672ff52df8b2c211b3f98cae4a88d8a96ccde0b
> 1aaaed7de0994f597c7f8290c722a0b4a7789429 Minclude
>
> I checked and tree is current and up to date and includes
> commit ee5242360424b9b967454e9183767323d10cf985
> Author: Christoph Hellwig
> Date: Tue Feb 21 10:04:55 2017 +0100
>
> scsi: zero per-cmd driver data before each I/O
>
> Kernel config is attached. It started with Ubuntu config, but then did
> localmodconfig and pruned
> out unnecessary stuff.
>
This problem I am seeing looks like the one addressed by:
Fixes: ee5242360424 ("scsi: zero per-cmd driver data before each I/O")
but that is already in linux-next.
Noticed another place where memset(of the data was being done not the extra
bits.
Tried this, but didn't fix it either...
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index ba2286652ff6..7e0463e78ff4 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1850,7 +1850,7 @@ static int scsi_mq_prep_fn(struct request *req)
/* zero out the cmd, except for the embedded scsi_request */
memset((char *)cmd + sizeof(cmd->req), 0,
- sizeof(*cmd) - sizeof(cmd->req));
+ sizeof(*cmd) - sizeof(cmd->req) + sdev->host->hostt->cmd_size);
req->special = cmd;
