michaelc@xxxxxxxxxxx wrote:
Aravind Parchuri wrote:
michaelc@xxxxxxxxxxx wrote:
Aravind Parchuri wrote:
My log messages were getting all mixed up, so I cleaned up my little
test to send just one command at a time. It actually looks like the mid
layer passes the command through to open-iscsi with the right size the
first time, but then it sends a second command with request_bufflen = 0.
I can verify that the command completed on the target just like the
regular ones did, so there should be no reason for a retry of any sort.
Here's the log for a 32896 byte command:
Mar 9 11:27:43 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcbadc000
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=32768, blk_size=32768
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_add_sfp: bufflen=32768,
k_use_sg=1
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_common_write: scsi
opcode=0x3b, cmd_size=10
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=32896
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=32896, blk_size=33280
Mar 8 11:27:43 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=32896,
iovec_count=0, k_use_sg=2
Mar 8 11:27:43 ITX000c292c3c8d kernel: iscsi_queuecommand: opcode 3b
request_bufflen 32896 transfersize 32896
Did you add your own output? Could you enable iscsi debugging? What
kernel is this with and what versions of open-iscsi (upstream or svn or
tarball release)?
No custom output, all of this is from scsi (SCSI_LOG_TIMEOUT=5) and
open-iscsi (DEBUG_SCSI enabled). I thought I mentioned this in an
earlier mail - the kernel is 2.6.19, but the open-iscsi drivers and
The output here does not have DEBUG_SCSI enabled. It just has your
custom iscsi output. The first log had DEBUG_SCSI iscsi output.
I'm extremely sorry - I think I forgot to enable it while recompiling
stuff with your patch, and I was fooled by that print that we put in
iscsi_queuecommand.
But what I want is not just parts you cut out. I am looking for all of
it. If I run:
sg_write_buffer /dev/sdi -l 32896
I wasn't aware that such a utility existed - it must be part of
sg_utils, I guess. I just hacked up a test to fire an SG_IO ioctl to a
given device. I guess I should try with this one next, just to check.
with my patch and a netapp target, I get the error:
Write buffer command not supported
If I look at the iscsi log, I see
Mar 12 12:59:54 madmax kernel: iscsi: cmd [itt 0x25 total 32896 imm_data
32896 unsol count 0, unsol offset 32896]
Mar 12 12:59:54 madmax kernel: iscsi: ctask enq [write cid 0 sc
ffff81000e82d6c0 cdb 0x3b itt 0x25 len 32896 cmdsn 294 win 128]
Mar 12 12:59:54 madmax kernel: iscsi: ctask deq [cid 0 xmstate 2 itt 0x25]
Mar 12 12:59:55 madmax kernel: iscsi: cmdrsp [op 0x21 cid 0 itt 0x25 len 24]
Mar 12 12:59:55 madmax kernel: iscsi: copied 22 bytes of sense
Mar 12 12:59:55 madmax kernel: iscsi: done [sc ffff81000e82d6c0 res 2
itt 0x25]
which shows the len got set and that the target failed the target and we
got some sense back. The command is then failed to sg and sg returns to
userspace.
Your output just shows that we may be retrying the same command over and
over and it never completes which would be strange because the command
is a block pc command. It would help to see what happens with iscsi's
DEBUG_SCSI option to see if the command failed or completed ok. It would
also be nice to get the scsi-ml output to see what the sense is and what
is going on there, but as a first step we can look at the iscsi output.
Thanks for explaining in detail what's useful in debugging the problem.
Here are logs with DEBUG_SCSI enabled, SCSI_LOG_TIMEOUT set to level 5,
SCSI_LOG_MLQUEUE to 4 and SCSI_LOG_MLCOMPLETE to 4. This is everything
in /var/log/messages from the time I issued the ioctl.
Command with 32896 bytes:
Mar 12 11:02:33 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt
0xffffffff datalen 0]
Mar 12 11:02:33 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4
itt 0xa05]
Mar 12 11:03:03 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt
0xffffffff datalen 0]
Mar 12 11:03:03 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4
itt 0xa06]
Mar 12 11:03:32 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt
0xffffffff datalen 0]
Mar 12 11:03:32 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4
itt 0xa07]
Mar 12 11:04:02 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt
0xffffffff datalen 0]
Mar 12 11:04:02 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4
itt 0xa08]
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcb554000
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=32768, blk_size=32768
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_add_sfp: bufflen=32768,
k_use_sg=1
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_common_write: scsi
opcode=0x3b, cmd_size=10
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=32896
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=32896, blk_size=33280
Mar 12 11:04:21 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=32896,
iovec_count=0, k_use_sg=2
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380
scsi 4:0:0:0:
Mar 12 11:04:21 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:21 ITX000c292c3c8d kernel: buffer = 0xd7497c80, bufflen =
32896, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: cmd [itt 0x3 total 32896
imm_data 32896 unsol count 0, unsol offset 32896]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: ctask enq [write cid 0 sc
d7b16380 cdb 0x3b itt 0x3 len 32896 cmdsn 4 win 257]
Mar 12 11:04:21 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate
2 itt 0x3]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt
0x3 len 0]
Mar 12 11:04:21 ITX000c292c3c8d kernel: iscsi: done [sc d7b16380 res 0
itt 0x3]
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16380
SUCCESS 0 scsi 4:0:0:0:
Mar 12 11:04:21 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:04:21 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper
driver of completion (result 0)
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380
scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: buffer = 0xd749be00, bufflen =
0, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: ctask enq [read cid 0 sc
d7b16380 cdb 0x3b itt 0x4 len 0 cmdsn 5 win 257]
Mar 12 11:04:22 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate
1 itt 0x4]
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt
0x4 len 0]
Mar 12 11:04:22 ITX000c292c3c8d kernel: iscsi: done [sc d7b16380 res 0
itt 0x4]
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16380
SUCCESS 0 scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper
driver of completion (result 0)
Mar 12 11:04:22 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16380
scsi 4:0:0:0:
Mar 12 11:04:22 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 80 80 00
Mar 12 11:04:22 ITX000c292c3c8d kernel: buffer = 0xd749be00, bufflen =
0, done = 0xd8876a7b, queuecommand 0xd8a9de6e
.
.
.
[repeats forever]
33k command (successfully completes):
Mar 12 11:00:19 ITX000c292c3c8d kernel: iscsi: mgmtpdu [op 0x40 hdr->itt
0xffffffff datalen 0]
Mar 12 11:00:19 ITX000c292c3c8d kernel: iscsi: mtask deq [cid 0 state 4
itt 0xa01]
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_open: dev=0, flags=0x802
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_add_sfp: sfp=0xcb43f000
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_reserve: req_size=32768
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=32768, blk_size=32768
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_add_sfp: bufflen=32768,
k_use_sg=1
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_ioctl: sg0, cmd=0x2285
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_common_write: scsi
opcode=0x3b, cmd_size=10
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_start_req: dxfer_len=33792
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_build_indirect:
buff_size=33792, blk_size=33792
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_write_xfer: num_xfer=33792,
iovec_count=0, k_use_sg=2
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: send 0xd7b16080
scsi 4:0:0:0:
Mar 12 11:00:35 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 84 00 00
Mar 12 11:00:35 ITX000c292c3c8d kernel: buffer = 0xd7497080, bufflen =
33792, done = 0xd8876a7b, queuecommand 0xd8a9de6e
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: cmd [itt 0x2 total 33792
imm_data 33792 unsol count 0, unsol offset 33792]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: ctask enq [write cid 0 sc
d7b16080 cdb 0x3b itt 0x2 len 33792 cmdsn 3 win 257]
Mar 12 11:00:35 ITX000c292c3c8d kernel: leaving scsi_dispatch_cmnd()
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: ctask deq [cid 0 xmstate
2 itt 0x2]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: cmdrsp [op 0x21 cid 0 itt
0x2 len 0]
Mar 12 11:00:35 ITX000c292c3c8d kernel: iscsi: done [sc d7b16080 res 0
itt 0x2]
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: done 0xd7b16080
SUCCESS 0 scsi 4:0:0:0:
Mar 12 11:00:35 ITX000c292c3c8d kernel: command: Write Buffer:
3b 01 01 00 00 00 00 84 00 00
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi host busy 1 failed 0
Mar 12 11:00:35 ITX000c292c3c8d kernel: scsi 4:0:0:0: Notifying upper
driver of completion (result 0)
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_cmd_done: sg0, pack_id=0, res=0x0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_finish_rem_req: res_used=0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_remove_scat: k_use_sg=2
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_release: sg0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_fasync: sg0, mode=0
Mar 12 11:00:35 ITX000c292c3c8d kernel: sg_remove_scat: k_use_sg=1
Also what target are you using?
We're using a slightly modified unh-iscsi target.
Aravind.
-
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
