| Message ID | 20170228172532.280811ed@xeon-e3 (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
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: 00000000: 00 aa be f1 5c 98 ff ff f0 64 > 02 89 ff ff ff ff > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > 00 00 00 00 00 00 > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff f0 64 > 02 89 ff ff ff ff > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > 00 00 00 00 00 00 > [ 1.362309] inquiry data: 00000020: 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
On Tue, 28 Feb 2017 22:20:58 -0800 James Bottomley <jejb@linux.vnet.ibm.com> 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: 00000000: 00 aa be f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [ 1.362309] inquiry data: 00000020: 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.
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
On Wed, 1 Mar 2017 16:50:57 +0100 Christoph Hellwig <hch@lst.de> 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))
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.
On Tue, 28 Feb 2017 22:20:58 -0800 James Bottomley <jejb@linux.vnet.ibm.com> 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: 00000000: 00 aa be f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff f0 64 > > 02 89 ff ff ff ff > > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 00 00 00 > > [ 1.362309] inquiry data: 00000020: 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: 00000000: 00 2e 64 71 db 97 ff ff f0 94 62 96 ff ff ff ff [ 1.012413] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 1.012414] data: 00000020: 00 00 00 00 Bad 4.11 initial INQUIRY buffer [ 1.218159] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 [ 1.225654] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 [ 1.242930] data: 00000020: 31 2e 30 20 Is the kmap_atomic looking at the right place?
On Wed, 2017-03-01 at 10:48 -0800, Stephen Hemminger wrote: > On Tue, 28 Feb 2017 22:20:58 -0800 > James Bottomley <jejb@linux.vnet.ibm.com> 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: 00000000: 00 aa be f1 5c 98 ff ff f0 > > > 64 > > > 02 89 ff ff ff ff > > > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 00 00 00 > > > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff f0 > > > 64 > > > 02 89 ff ff ff ff > > > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 00 00 00 > > > [ 1.362309] inquiry data: 00000020: 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: 00000000: 00 2e 64 71 db 97 ff ff f0 94 62 96 ff > ff ff ff > [ 1.012413] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 > [ 1.012414] data: 00000020: 00 00 00 00 > > Bad 4.11 initial INQUIRY buffer > [ 1.218159] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 20 > 20 20 20 > [ 1.225654] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 > 20 20 20 > [ 1.242930] data: 00000020: 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
On Wed, Mar 1, 2017 at 10:48 AM, Stephen Hemminger <stephen@networkplumber.org> wrote: > > Bad 4.11 initial INQUIRY buffer > [ 1.218159] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 > [ 1.225654] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 > [ 1.242930] data: 00000020: 31 2e 30 20 "........Msft Virtual Disk 1.0 ." in case anybody wondered about what the ascii data was, like I did. Linus
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 <jejb@linux.vnet.ibm.com> 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: 00000000: 00 aa be f1 5c 98 ff ff > > > > f0 > > > > 64 > > > > 02 89 ff ff ff ff > > > > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 > > > > 00 > > > > 00 > > > > 00 00 00 00 00 00 > > > > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff > > > > f0 > > > > 64 > > > > 02 89 ff ff ff ff > > > > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 > > > > 00 > > > > 00 > > > > 00 00 00 00 00 00 > > > > [ 1.362309] inquiry data: 00000020: 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: 00000000: 00 2e 64 71 db 97 ff ff f0 94 62 96 > > ff > > ff ff ff > > [ 1.012413] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 > > 00 00 00 > > [ 1.012414] data: 00000020: 00 00 00 00 > > > > Bad 4.11 initial INQUIRY buffer > > [ 1.218159] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 > > 20 > > 20 20 20 > > [ 1.225654] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b > > 20 > > 20 20 20 > > [ 1.242930] data: 00000020: 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
On Wed, 01 Mar 2017 11:20:22 -0800 James Bottomley <James.Bottomley@HansenPartnership.com> 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 <jejb@linux.vnet.ibm.com> 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: 00000000: 00 aa be f1 5c 98 ff ff > > > > > f0 > > > > > 64 > > > > > 02 89 ff ff ff ff > > > > > [ 1.356543] inquiry data: 00000010: 00 00 00 00 00 00 00 00 > > > > > 00 > > > > > 00 > > > > > 00 00 00 00 00 00 > > > > > [ 1.359996] inquiry data: 00000020: 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: 00000000: 00 23 34 f1 5c 98 ff ff > > > > > f0 > > > > > 64 > > > > > 02 89 ff ff ff ff > > > > > [ 1.362309] inquiry data: 00000010: 00 00 00 00 00 00 00 00 > > > > > 00 > > > > > 00 > > > > > 00 00 00 00 00 00 > > > > > [ 1.362309] inquiry data: 00000020: 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: 00000000: 00 2e 64 71 db 97 ff ff f0 94 62 96 > > > ff > > > ff ff ff > > > [ 1.012413] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 > > > 00 > > > 00 00 00 > > > [ 1.012414] data: 00000020: 00 00 00 00 > > > > > > Bad 4.11 initial INQUIRY buffer > > > [ 1.218159] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 > > > 20 > > > 20 20 20 > > > [ 1.225654] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b > > > 20 > > > 20 20 20 > > > [ 1.242930] data: 00000020: 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
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 0x1f15d0000 virt ffff9270b15d0000 offset 0xc00 length 36 [ 1.031720] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 ........Msft [ 1.033846] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 Virtual Disk [ 1.036080] data: 00000020: 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 ffff9270b0faf000 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 ffff9270b15d6000 offset 0xb00 length 36 [ 1.048559] data: 00000000: 05 80 00 02 1f 00 00 00 4d 73 66 74 20 20 20 20 ........Msft [ 1.048560] data: 00000010: 56 69 72 74 75 61 6c 20 44 56 44 2d 52 4f 4d 20 Virtual DVD-ROM [ 1.048560] data: 00000020: 31 2e 30 20 1.0 [ 1.048590] scsi 1:0:0:0: CD-ROM Msft 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 ffff9270b15d7000 offset 0x400 length 36 [ 1.048922] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.048923] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.048923] data: 00000020: 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 ffff9a42f1196000 offset 0x300 length 36 [ 1.545242] data: 00000000: 00 00 05 02 1f 00 00 02 4d 73 66 74 20 20 20 20 ........Msft [ 1.545242] data: 00000010: 56 69 72 74 75 61 6c 20 44 69 73 6b 20 20 20 20 Virtual Disk [ 1.545242] data: 00000020: 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 ffff9a42f0577000 offset 0x0 length 255 [ 1.612788] data: 00000000: 00 00 00 08 00 83 8f b0 b1 b2 ce cf 72 65 61 74 ............reat [ 1.612788] data: 00000010: 65 5f 66 69 6c 65 00 5f 5f 63 72 63 5f 68 69 64 e_file.__crc_hid [ 1.612788] data: 00000020: 5f 72 65 70 6f 72 74 5f 72 61 77 5f 65 76 65 6e _report_raw_even [ 1.612788] data: 00000030: 74 00 76 66 72 65 65 00 75 6e 72 65 67 69 73 74 t.vfree.unregist [ 1.612788] data: 00000040: 65 72 5f 63 68 72 64 65 76 5f 72 65 67 69 6f 6e er_chrdev_region [ 1.612788] data: 00000050: 00 6d 75 74 65 78 5f 75 6e 6c 6f 63 6b 00 68 69 .mutex_unlock.hi [ 1.612788] data: 00000060: 64 5f 64 65 62 75 67 5f 65 78 69 74 00 6b 6d 65 d_debug_exit.kme [ 1.612788] data: 00000070: 6d 64 75 70 00 68 69 64 72 61 77 5f 65 78 69 74 mdup.hidraw_exit [ 1.612788] data: 00000080: 00 5f 5f 67 65 74 5f 75 73 65 72 5f 34 00 70 6f .__get_user_4.po [ 1.612788] data: 00000090: 77 65 72 5f 73 75 70 70 6c 79 5f 70 6f 77 65 72 wer_supply_power [ 1.612788] data: 000000a0: 73 00 64 65 76 69 63 65 5f 64 65 73 74 72 6f 79 s.device_destroy [ 1.612788] data: 000000b0: 00 5f 5f 63 72 63 5f 68 69 64 5f 73 6e 74 6f 33 .__crc_hid_snto3 [ 1.612788] data: 000000c0: 32 00 63 61 6e 63 65 6c 5f 77 6f 72 6b 5f 73 79 2.cancel_work_sy [ 1.612788] data: 000000d0: 6e 63 00 73 65 71 5f 70 72 69 6e 74 66 00 64 6f nc.seq_printf.do [ 1.612788] data: 000000e0: 77 6e 5f 69 6e 74 65 72 72 75 70 74 69 62 6c 65 wn_interruptible [ 1.612788] data: 000000f0: 00 5f 5f 63 72 63 5f 68 69 64 5f 70 61 72 73 .__crc_hid_pars [ 1.649097] hv_storvsc: INQUIRY cmd 0x12 0x1 0x83 scsi status 0x0 srb status 0x1 length 52 [ 1.649097] random: fast init done [ 1.649097] hv_storvsc: payload size 288 count 1 offset 0 len 255 pfn 0x1f0576 [ 1.649097] hv_storvsc: sg 0: phys 0x1f0576000 virt ffff9a42f0576000 offset 0x0 length 255 [ 1.649097] data: 00000000: 00 83 00 30 01 01 00 18 4d 53 46 54 20 20 20 20 ...0....MSFT [ 1.649097] data: 00000010: 43 77 cc 85 5f 19 c2 46 ac 48 c7 33 b9 dd 2d 2a Cw.._..F.H.3..-* [ 1.649097] data: 00000020: 01 03 00 10 60 02 24 80 43 77 cc 85 5f 19 c7 33 ....`.$.Cw.._..3 [ 1.649097] data: 00000030: b9 dd 2d 2a 5f 55 4e 49 51 55 45 5f 49 44 5f 69 ..-*_UNIQUE_ID_i [ 1.649097] data: 00000040: 67 6e 6f 72 65 5f 73 70 65 63 69 61 6c 5f 64 72 gnore_special_dr [ 1.649097] data: 00000050: 69 76 65 72 73 74 79 70 65 31 34 00 5f 5f 70 61 iverstype14.__pa [ 1.649097] data: 00000060: 72 61 6d 5f 69 67 6e 6f 72 65 5f 73 70 65 63 69 ram_ignore_speci [ 1.649097] data: 00000070: 61 6c 5f 64 72 69 76 65 72 73 00 5f 5f 70 61 72 al_drivers.__par [ 1.649097] data: 00000080: 61 6d 5f 73 74 72 5f 69 67 6e 6f 72 65 5f 73 70 am_str_ignore_sp [ 1.649097] data: 00000090: 65 63 69 61 6c 5f 64 72 69 76 65 72 73 00 5f 5f ecial_drivers.__ [ 1.649097] data: 000000a0: 6b 73 79 6d 74 61 62 5f 68 69 64 5f 64 65 62 75 ksymtab_hid_debu [ 1.649097] data: 000000b0: 67 00 5f 5f 6b 73 74 72 74 61 62 5f 68 69 64 5f g.__kstrtab_hid_ [ 1.649097] data: 000000c0: 64 65 62 75 67 00 5f 5f 55 4e 49 51 55 45 5f 49 debug.__UNIQUE_I [ 1.649097] data: 000000d0: 44 5f 64 65 62 75 67 31 33 00 5f 5f 55 4e 49 51 D_debug13.__UNIQ [ 1.649097] data: 000000e0: 55 45 5f 49 44 5f 64 65 62 75 67 74 79 70 65 31 UE_ID_debugtype1 [ 1.649097] data: 000000f0: 32 00 5f 5f 70 61 72 61 6d 5f 64 65 62 75 67 2.__param_debug [ 1.805271] input: Microsoft Vmbus HID-compliant Mouse as /devices/0006:045E:0621.0001/input/input1 [ 1.805350] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x1 length 36 [ 1.805351] hv_storvsc: payload size 288 count 1 offset 2304 len 36 pfn 0x1f1988 [ 1.805352] hv_storvsc: sg 0: phys 0x1f1988000 virt ffff9a42f1988000 offset 0x900 length 36 [ 1.805353] data: 00000000: 05 80 00 02 1f 00 00 00 4d 73 66 74 20 20 20 20 ........Msft [ 1.805353] data: 00000010: 56 69 72 74 75 61 6c 20 44 56 44 2d 52 4f 4d 20 Virtual DVD-ROM [ 1.805354] data: 00000020: 31 2e 30 20 1.0 [ 1.805379] scsi 1:0:0:0: CD-ROM Msft Virtual DVD-ROM 1.0 PQ: 0 ANSI: 0 [ 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 ffff9a42f198b000 offset 0xb00 length 36 [ 1.812953] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.812953] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.812954] data: 00000020: 00 00 00 00 .... [ 1.813258] scsi host1: scsi scan: INQUIRY result too short (5), using 36 [ 1.813271] scsi 1:0:0:1: Direct-Access PQ: 0 ANSI: 0 [ 1.817903] hv_storvsc: INQUIRY cmd 0x12 0x0 0x0 scsi status 0x0 srb status 0x20 length 36 [ 1.817921] hv_storvsc: payload size 288 count 1 offset 2048 len 36 pfn 0x1f198a [ 1.817932] hv_storvsc: sg 0: phys 0x1f198a000 virt ffff9a42f198a000 offset 0x800 length 36 [ 1.817940] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.817941] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ [ 1.817941] data: 00000020: 00 00 00 00 .... The response from offline DVD device is shorter and contains stale data.
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 > ffff9270b15d7000 offset 0x400 length 36 > [ 1.048922] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 ................ > [ 1.048923] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 ................ > [ 1.048923] data: 00000020: 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 > ffff9a42f198b000 offset 0xb00 length 36 > [ 1.812953] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 ................ > [ 1.812953] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > 00 00 00 ................ > [ 1.812954] data: 00000020: 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
On Wed, 01 Mar 2017 15:09:44 -0800 James Bottomley <James.Bottomley@HansenPartnership.com> 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 > > ffff9270b15d7000 offset 0x400 length 36 > > [ 1.048922] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 ................ > > [ 1.048923] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 ................ > > [ 1.048923] data: 00000020: 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 > > ffff9a42f198b000 offset 0xb00 length 36 > > [ 1.812953] data: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 ................ > > [ 1.812953] data: 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 > > 00 00 00 ................ > > [ 1.812954] data: 00000020: 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.
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: