DataDigest corruption with Wasabi target

[Albert Pauw]

Chris Machut of Wasabisystems was kind enough to let me test their
target (StorageBuilder). Although at the moment I had only a ADSL
connection (1 MB up, 4 MB down) I was able to test open-iscsi with
their target. I used Fedora Core 3 with the latest kernel incarnation
(2.6.12-1.1380_FC3) and the latest SVN version of open-iscsi (r424).

I have put several GB of data on it and checked integrity, and did some
more testing changing parameters.

Here are my findings:

- open-iscsi can login fine, both without credentials and with it
(CHAP).
- I had no datacorruption on the 7GB of data (took a loooong time).
- HeaderDigest works fine, setting it to None or CRC32C, no problems.
- DataDigest works fine for None, however when set to CRC32C I had a
datacorruption as even the partition table wasn't recognised anymore.
Switching back both target and initiator to None and logging in again
confirmed that the partition table still was there.

The dmesg command shows the following consistently, when DataDigest was
forced to CRC32C:

Vendor: Wasabi Model: WSB 1500i Rev: 0155
Type: Direct-Access ANSI SCSI revision: 05
iscsi_tcp: datalen 8388608 > 131072
iscsi9: detected conn error (1006)

And here is some output from "iscsid -d8 -f":

iscsid: sending login PDU with current stage 1, next stage 3, transit
0x80, isid 0x00023d000000
iscsid: > HeaderDigest=None
iscsid: > DataDigest=CRC32C
iscsid: > DefaultTime2Wait=2
iscsid: > DefaultTime2Retain=0
iscsid: > IFMarker=No
iscsid: > OFMarker=No
iscsid: > ErrorRecoveryLevel=0
iscsid: > InitialR2T=No
iscsid: > ImmediateData=Yes
iscsid: > MaxBurstLength=262144
iscsid: > FirstBurstLength=65536
iscsid: > MaxOutstandingR2T=1
iscsid: > MaxConnections=1
iscsid: > DataPDUInOrder=Yes
iscsid: > DataSequenceInOrder=Yes
iscsid: > MaxRecvDataSegmentLength=131072
iscsid: > X-com.cisco.PingTimeout=5
iscsid: > X-com.cisco.sendAsyncText=No
iscsid: > X-com.cisco.protocol=draft20
iscsid: send PDU began for hdr 48 bytes and data 396 bytes
iscsid: wrote 48 bytes of PDU header
iscsid: wrote 396 bytes of PDU data
iscsid: send PDU finished for conn (handle 0xd3472c00)
iscsid: detected poll event 1
iscsid: message real length is 468 bytes, recv_handle 0x875d830
iscsid: recv PDU began, pdu handle 0x0x875d830
iscsid: read 48 bytes of PDU header
iscsid: read 48 PDU header bytes, opcode 0x23, dlength 348, data
0xb7eda4f8, max 8192
iscsid: read 348 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 348 data, 0 pad
iscsid: login current stage 1, next stage 3, transit 0x80
iscsid: > X-com.cisco.PingTimeout=NotUnderstood
iscsid: > X-com.cisco.sendAsyncText=NotUnderstood
iscsid: > X-com.cisco.protocol=NotUnderstood
iscsid: > HeaderDigest=None
iscsid: > DataDigest=CRC32C
iscsid: > MaxConnections=1
iscsid: > OFMarker=No
iscsid: > IFMarker=No
iscsid: > InitialR2T=No
iscsid: > ImmediateData=Yes
iscsid: > MaxBurstLength=262144
iscsid: > FirstBurstLength=65536
iscsid: > DefaultTime2Retain=0
iscsid: > DefaultTime2Wait=2
iscsid: > MaxOutstandingR2T=1
iscsid: > ErrorRecoveryLevel=0
iscsid: recv PDU finished for pdu handle 0x0x875d830
iscsid: deleting a scheduled/waiting thread!
iscsid: login response status 0000
iscsid: set operational parameter 0 to 131072
iscsid: set operational parameter 1 to 8192
iscsid: set operational parameter 2 to 0
iscsid: set operational parameter 3 to 1
iscsid: set operational parameter 4 to 0
iscsid: set operational parameter 5 to 1
iscsid: set operational parameter 6 to 1
iscsid: set operational parameter 7 to 65536
iscsid: set operational parameter 8 to 262144
iscsid: set operational parameter 9 to 0
iscsid: set operational parameter 10 to 0
iscsid: set operational parameter 11 to 0
iscsid: set operational parameter 14 to 0
iscsid: connection10:0 is operational after recovery (1 attempts)

Any idea what more to check?

Thanks,

Albert

[Wang Zhenyu]

On 2005.10.22 11:50:45 +0000, Albert Pauw wrote:
>
> Chris Machut of Wasabisystems was kind enough to let me test their
> target (StorageBuilder). Although at the moment I had only a ADSL
> connection (1 MB up, 4 MB down) I was able to test open-iscsi with
> their target. I used Fedora Core 3 with the latest kernel incarnation
> (2.6.12-1.1380_FC3) and the latest SVN version of open-iscsi (r424).
>
> I have put several GB of data on it and checked integrity, and did some
> more testing changing parameters.
>
> Here are my findings:
>
> - open-iscsi can login fine, both without credentials and with it
> (CHAP).
> - I had no datacorruption on the 7GB of data (took a loooong time).
> - HeaderDigest works fine, setting it to None or CRC32C, no problems.
> - DataDigest works fine for None, however when set to CRC32C I had a
> datacorruption as even the partition table wasn't recognised anymore.
> Switching back both target and initiator to None and logging in again
> confirmed that the partition table still was there.
>
> The dmesg command shows the following consistently, when DataDigest was
> forced to CRC32C:
>
> Vendor: Wasabi Model: WSB 1500i Rev: 0155
> Type: Direct-Access ANSI SCSI revision: 05
> iscsi_tcp: datalen 8388608 > 131072
> iscsi9: detected conn error (1006)
>

for debug this, you may enable DEBUG_TCP, and send the kernel logs.

thanks
zhen

[Albert Pauw]

>
> for debug this, you may enable DEBUG_TCP, and send the kernel logs.
>
> thanks
> zhen

Thanks Zhen,

here's the output from /var/log/messages, it's quite a bit, but maybe
does it say something to you?

I had set the target to DataDigest CRC32C required, and did the same in
the .db files of iscsiadm.

Albert

---

iscsi: registered transport (tcp)
scsi20 : iSCSI Initiator over TCP/IP, v.0.3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 180 bytes, sent 0 left 180 sent 0 res 180
tcp: in 88 bytes
tcp: opcode 0x23 offset 48 copy 40 ahslen 0 datalen 39
tcp: data_recv offset 48 copy 40
tcp: tcp_copy 39 bytes at offset 48 copied 0
tcp: f, processed 88 from out of 88 padding 1
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 12 bytes, sent 0 left 12 sent 180 res 12
tcp: in 96 bytes
tcp: opcode 0x23 offset 48 copy 48 ahslen 0 datalen 45
tcp: data_recv offset 48 copy 48
tcp: tcp_copy 45 bytes at offset 48 copied 0
tcp: f, processed 96 from out of 96 padding 3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 60 bytes, sent 0 left 60 sent 192 res 60
tcp: in 48 bytes
tcp: opcode 0x23 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 392 bytes, sent 0 left 392 sent 252 res 392
tcp: in 384 bytes
tcp: opcode 0x23 offset 48 copy 336 ahslen 0 datalen 336
tcp: data_recv offset 48 copy 336
tcp: tcp_copy 336 bytes at offset 48 copied 0
tcp: f, processed 384 from out of 384 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 88 bytes
tcp: opcode 0x25 offset 48 copy 40 ahslen 0 datalen 36
tcp: data_recv offset 48 copy 40
tcp: ctask_copy 36 bytes at offset 48 copied 0
tcp: rx digest 0xd88a7517
tcp: f, processed 84 from out of 88 padding 0
tcp: continue to process 4 bytes
tcp: extra data_recv offset 84 copy 4
tcp: iscsi_tcp: data digest match!0xd88a7517 == 0xd88a7517
tcp: f, processed 88 from out of 88 padding 0
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 120 bytes
tcp: opcode 0x25 offset 48 copy 72 ahslen 0 datalen 66
tcp: data_recv offset 48 copy 72
tcp: ctask_copy 66 bytes at offset 48 copied 0
tcp: padding -> 2
tcp: rx digest 0x4448b661
tcp: f, processed 116 from out of 120 padding 2
tcp: continue to process 4 bytes
tcp: extra data_recv offset 116 copy 4
tcp: iscsi_tcp: data digest match!0x4448b661 == 0x4448b661
tcp: f, processed 120 from out of 120 padding 2
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0

Vendor: Wasabi Model: WSB 1500i Rev: 0155
Type: Direct-Access ANSI SCSI revision: 05

tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 72 bytes
tcp: opcode 0x21 offset 48 copy 24 ahslen 0 datalen 20
tcp: data_recv offset 48 copy 24
tcp: tcp_copy 20 bytes at offset 48 copied 0
tcp: f, processed 68 from out of 72 padding 0
tcp: continue to process 4 bytes
tcp: PDU gather offset 0 bytes 4 in.offset 68 in.copy 4
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 48 bytes
tcp: PDU gather offset 4 bytes 44 in.offset 0 in.copy 48
iscsi_tcp: datalen 8388608 > 4096
iscsi20: detected conn error (1006)
tcp: in 48 bytes
tcp: conn 0 Rx suspended!
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 180 bytes, sent 0 left 180 sent 644 res 180
tcp: in 88 bytes
tcp: opcode 0x23 offset 48 copy 40 ahslen 0 datalen 39
tcp: data_recv offset 48 copy 40
tcp: tcp_copy 39 bytes at offset 48 copied 0
tcp: f, processed 88 from out of 88 padding 1
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 12 bytes, sent 0 left 12 sent 824 res 12
tcp: in 96 bytes
tcp: opcode 0x23 offset 48 copy 48 ahslen 0 datalen 45
tcp: data_recv offset 48 copy 48
tcp: tcp_copy 45 bytes at offset 48 copied 0
tcp: f, processed 96 from out of 96 padding 3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 60 bytes, sent 0 left 60 sent 836 res 60
tcp: in 48 bytes
tcp: opcode 0x23 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 388 bytes, sent 0 left 388 sent 896 res 388
tcp: in 380 bytes
tcp: opcode 0x23 offset 48 copy 332 ahslen 0 datalen 332
tcp: data_recv offset 48 copy 332
tcp: tcp_copy 332 bytes at offset 48 copied 0
tcp: f, processed 380 from out of 380 padding 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
scsi: Device offlined - not ready after error recovery: host 20 channel
0 id 0 lun 0
scsi20 (0:0): rejecting I/O to offline device
scsi20 (0:0): rejecting I/O to offline device
scsi20 (0:0): rejecting I/O to offline device
sda : READ CAPACITY failed.
sda : status=0, message=00, host=0, driver=06
sda : sense not available.
scsi20 (0:0): rejecting I/O to offline device
sda: asking for cache data failed
sda: assuming drive cache: write through
Attached scsi disk sda at scsi20, channel 0, id 0, lun 0
scsi20 (0:0): rejecting I/O to offline device
scsi20 (0:0): rejecting I/O to offline device
scsi20 (0:0): rejecting I/O to offline device
iscsi_tcp: cmd 0x12 is not queued (5)
conn_destroy(): host_busy 0 host_failed 0
KERNEL: assertion (!atomic_read(&sk->sk_rmem_alloc)) failed at
net/netlink/af_netlink.c (122)
iscsi: registered transport (tcp)
input: AT Translated Set 2 keyboard on isa0060/serio0
iscsi: registered transport (tcp)
scsi21 : iSCSI Initiator over TCP/IP, v.0.3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 180 bytes, sent 0 left 180 sent 0 res 180
tcp: in 88 bytes
tcp: opcode 0x23 offset 48 copy 40 ahslen 0 datalen 39
tcp: data_recv offset 48 copy 40
tcp: tcp_copy 39 bytes at offset 48 copied 0
tcp: f, processed 88 from out of 88 padding 1
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 12 bytes, sent 0 left 12 sent 180 res 12
tcp: in 96 bytes
tcp: opcode 0x23 offset 48 copy 48 ahslen 0 datalen 45
tcp: data_recv offset 48 copy 48
tcp: tcp_copy 45 bytes at offset 48 copied 0
tcp: f, processed 96 from out of 96 padding 3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 60 bytes, sent 0 left 60 sent 192 res 60
tcp: in 48 bytes
tcp: opcode 0x23 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 392 bytes, sent 0 left 392 sent 252 res 392
tcp: in 384 bytes
tcp: opcode 0x23 offset 48 copy 336 ahslen 0 datalen 336
tcp: data_recv offset 48 copy 336
tcp: tcp_copy 336 bytes at offset 48 copied 0
tcp: f, processed 384 from out of 384 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 88 bytes
tcp: opcode 0x25 offset 48 copy 40 ahslen 0 datalen 36
tcp: data_recv offset 48 copy 40
tcp: ctask_copy 36 bytes at offset 48 copied 0
tcp: rx digest 0xd88a7517
tcp: f, processed 84 from out of 88 padding 0
tcp: continue to process 4 bytes
tcp: extra data_recv offset 84 copy 4
tcp: iscsi_tcp: data digest match!0xd88a7517 == 0xd88a7517
tcp: f, processed 88 from out of 88 padding 0
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 120 bytes
tcp: opcode 0x25 offset 48 copy 72 ahslen 0 datalen 66
tcp: data_recv offset 48 copy 72
tcp: ctask_copy 66 bytes at offset 48 copied 0
tcp: padding -> 2
tcp: rx digest 0x4448b661
tcp: f, processed 116 from out of 120 padding 2
tcp: continue to process 4 bytes
tcp: extra data_recv offset 116 copy 4
tcp: iscsi_tcp: data digest match!0x4448b661 == 0x4448b661
tcp: f, processed 120 from out of 120 padding 2
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0

Vendor: Wasabi Model: WSB 1500i Rev: 0155
Type: Direct-Access ANSI SCSI revision: 05

tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 72 bytes
tcp: opcode 0x21 offset 48 copy 24 ahslen 0 datalen 20
tcp: data_recv offset 48 copy 24
tcp: tcp_copy 20 bytes at offset 48 copied 0
tcp: f, processed 68 from out of 72 padding 0
tcp: continue to process 4 bytes
tcp: PDU gather offset 0 bytes 4 in.offset 68 in.copy 4
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: in 48 bytes
tcp: PDU gather offset 4 bytes 44 in.offset 0 in.copy 48
iscsi_tcp: datalen 8388608 > 4096
iscsi21: detected conn error (1006)
tcp: in 48 bytes
tcp: conn 0 Rx suspended!
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 180 bytes, sent 0 left 180 sent 644 res 180
tcp: in 88 bytes
tcp: opcode 0x23 offset 48 copy 40 ahslen 0 datalen 39
tcp: data_recv offset 48 copy 40
tcp: tcp_copy 39 bytes at offset 48 copied 0
tcp: f, processed 88 from out of 88 padding 1
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 12 bytes, sent 0 left 12 sent 824 res 12
tcp: in 96 bytes
tcp: opcode 0x23 offset 48 copy 48 ahslen 0 datalen 45
tcp: data_recv offset 48 copy 48
tcp: tcp_copy 45 bytes at offset 48 copied 0
tcp: f, processed 96 from out of 96 padding 3
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 60 bytes, sent 0 left 60 sent 836 res 60
tcp: in 48 bytes
tcp: opcode 0x23 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0
tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 388 bytes, sent 0 left 388 sent 896 res 388
tcp: in 380 bytes
tcp: opcode 0x23 offset 48 copy 332 ahslen 0 datalen 332
tcp: data_recv offset 48 copy 332
tcp: tcp_copy 332 bytes at offset 48 copied 0
tcp: f, processed 380 from out of 380 padding 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
conn_destroy(): host_busy 1 host_failed 0
scsi: Device offlined - not ready after error recovery: host 21 channel
0 id 0 lun 0
scsi21 (0:0): rejecting I/O to offline device
scsi21 (0:0): rejecting I/O to offline device
scsi21 (0:0): rejecting I/O to offline device
sda : READ CAPACITY failed.
sda : status=0, message=00, host=0, driver=06
sda : sense not available.
scsi21 (0:0): rejecting I/O to offline device
sda: asking for cache data failed
sda: assuming drive cache: write through
Attached scsi disk sda at scsi21, channel 0, id 0, lun 0
scsi21 (0:0): rejecting I/O to offline device
scsi21 (0:0): rejecting I/O to offline device
scsi21 (0:0): rejecting I/O to offline device
iscsi_tcp: cmd 0x12 is not queued (5)
conn_destroy(): host_busy 0 host_failed 0

[Wang Zhenyu]

On 2005.10.24 00:56:50 +0000, Albert Pauw wrote:
> >
> > for debug this, you may enable DEBUG_TCP, and send the kernel logs.
> >
> > thanks
> > zhen
>
> Thanks Zhen,
>
> here's the output from /var/log/messages, it's quite a bit, but maybe
> does it say something to you?
>
> I had set the target to DataDigest CRC32C required, and did the same in
> the .db files of iscsiadm.
>
> Albert
>

thanks, it shows some bug there with data digest handling PDU gather
across skbs, which i might ignore before.
I'll take a look at that.

zhen

[Wang Zhenyu]

ok, this's wrong. The real problem here is that I wrongly hardcoded data
digest handling only for data-in pdus. So in Albert's case, scsi cmd rsp
supports autosense with sense data, then finally state machine corrupt.

Sorry for my mistake! and here goes the patch. Albert, pls test it.

thanks

Signed-off-by: Wang Zhenyu <zhenyu...@intel.com>
---

--- kernel/iscsi_tcp.c.orig 2005-10-24 23:13:00.730937600 +0800
+++ kernel/iscsi_tcp.c 2005-10-24 23:24:55.739068800 +0800
@@ -1111,8 +1111,7 @@ more:
*/
rc = iscsi_hdr_recv(conn);
if (!rc && conn->in.datalen) {
- if (conn->datadgst_en &&
- conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {
+ if (conn->datadgst_en) {
BUG_ON(!conn->data_rx_tfm);
crypto_digest_init(conn->data_rx_tfm);
}
@@ -1124,26 +1123,24 @@ more:
}

if (conn->in_progress == IN_PROGRESS_DDIGEST_RECV) {
+ uint32_t recv_digest;
debug_tcp("extra data_recv offset %d copy %d\n",
conn->in.offset, conn->in.copy);
- if (conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {
- uint32_t recv_digest;
- skb_copy_bits(conn->in.skb, conn->in.offset,
- &recv_digest, 4);
- conn->in.offset += 4;
- conn->in.copy -= 4;
- if (recv_digest != conn->in.datadgst) {
- debug_tcp("iscsi_tcp: data digest error!"
- "0x%x != 0x%x\n", recv_digest,
- conn->in.datadgst);
- iscsi_conn_failure(conn, ISCSI_ERR_DATA_DGST);
- return 0;
- } else {
- debug_tcp("iscsi_tcp: data digest match!"
- "0x%x == 0x%x\n", recv_digest,
- conn->in.datadgst);
- conn->in_progress = IN_PROGRESS_WAIT_HEADER;
- }
+ skb_copy_bits(conn->in.skb, conn->in.offset,
+ &recv_digest, 4);
+ conn->in.offset += 4;
+ conn->in.copy -= 4;
+ if (recv_digest != conn->in.datadgst) {
+ debug_tcp("iscsi_tcp: data digest error!"
+ "0x%x != 0x%x\n", recv_digest,
+ conn->in.datadgst);
+ iscsi_conn_failure(conn, ISCSI_ERR_DATA_DGST);
+ return 0;
+ } else {
+ debug_tcp("iscsi_tcp: data digest match!"
+ "0x%x == 0x%x\n", recv_digest,
+ conn->in.datadgst);
+ conn->in_progress = IN_PROGRESS_WAIT_HEADER;
}
}

@@ -1164,8 +1161,7 @@ more:
}
conn->in.copy -= conn->in.padding;
conn->in.offset += conn->in.padding;
- if (conn->datadgst_en &&
- conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {
+ if (conn->datadgst_en) {
if (conn->in.padding) {
debug_tcp("padding -> %d\n", conn->in.padding);
memset(pad, 0, conn->in.padding);

[Albert Pauw]

Wang Zhenyu wrote:

>
> ok, this's wrong. The real problem here is that I wrongly hardcoded data
> digest handling only for data-in pdus. So in Albert's case, scsi cmd rsp
> supports autosense with sense data, then finally state machine corrupt.
>
> Sorry for my mistake! and here goes the patch. Albert, pls test it.
>
> thanks
>

Hi Zhen,

I am going to test this today and let you know if I encounter any
problems.

Regards,

Albert

[Albert Pauw]

> Hi Zhen,
>
> I am going to test this today and let you know if I encounter any
> problems.
>
> Regards,
>
> Albert

Hi Zhen,

bad news. Although iscsiadm returns to the command probe, a "iscsid -d8
-f" output shows the stuff at the bottom and keeps looping/trying.

dmesg shows the following:

SCSI subsystem initialized
iscsi: registered transport (tcp)
scsi0 : iSCSI Initiator over TCP/IP, v.0.3

Vendor: Wasabi Model: WSB 1500i Rev: 0155
Type: Direct-Access ANSI SCSI revision: 05

iscsi0: detected conn error (1015)
iscsi0: detected conn error (1015)
iscsi0: detected conn error (1015)
iscsi0: detected conn error (1015)

---- output of iscsid -d8 -f:

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: bound iSCSI connection (handle 0x0xd2aa9000) to session (handle
0x0xd1426668)
iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes
iscsid: thread b7f5c518 schedule: delay 60 state 2
iscsid: send_pdu timer added 15 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 160 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 1 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 1
iscsid: event_type: 1 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: in krecv_pdu_begin
iscsid: recv PDU began, pdu handle 0x0x95dd830
iscsid: in kread

iscsid: read 48 bytes of PDU header

iscsid: read 48 PDU header bytes, opcode 0x23, dlength 39, data
0xb7f5a4f8, max 8192
iscsid: in kread
iscsid: read 39 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 39 data, 3 pad
iscsid: login current stage 0, next stage 0, transit 0x0
iscsid: > AuthMethod=CHAP
iscsid: > TargetPortalGroupTag=1
iscsid: in krecv_pdu_end
iscsid: recv PDU finished for pdu handle 0x0x95dd830
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed

iscsid: login response status 0000

iscsid: sending login PDU with current stage 0, next stage 0, transit
0x0, isid 0x00023d000000
iscsid: > CHAP_A=5
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 12 bytes
iscsid: thread b7f5c518 schedule: delay 180 state 2
iscsid: send_pdu timer added 45 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 12 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c removed from actor_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 72 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 4 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: event_type: 4 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: detected iSCSI connection (handle 0xd2aa9000) error (1015)
state (2)
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed
iscsid: re-opening session 0 (reopen_cnt 14)
iscsid: in kstop_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: connection 0x0xd2aa9000 is stopped for recovery
iscsid: disconnecting conn 0xb7f5a478, fd 5
iscsid: flushing per-connection events
iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f5c4fc schedule: delay 60 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list
iscsid: thread b7f5c4fc wait some more
iscsid: event_type: 2 removing from the head:
0x0x95d9828:0x0x95d983c:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: connected local port 54097 to 66.173.145.126:3260
iscsid: thread b7f5c4fc delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: bound iSCSI connection (handle 0x0xd2aa9000) to session (handle
0x0xd1426668)
iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes
iscsid: thread b7f5c518 schedule: delay 60 state 2
iscsid: send_pdu timer added 15 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 160 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 1 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 1
iscsid: event_type: 1 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: in krecv_pdu_begin
iscsid: recv PDU began, pdu handle 0x0x95dd830
iscsid: in kread

iscsid: read 48 bytes of PDU header

iscsid: read 48 PDU header bytes, opcode 0x23, dlength 39, data
0xb7f5a4f8, max 8192
iscsid: in kread
iscsid: read 39 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 39 data, 3 pad
iscsid: login current stage 0, next stage 0, transit 0x0
iscsid: > AuthMethod=CHAP
iscsid: > TargetPortalGroupTag=1
iscsid: in krecv_pdu_end
iscsid: recv PDU finished for pdu handle 0x0x95dd830
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed

iscsid: login response status 0000

iscsid: sending login PDU with current stage 0, next stage 0, transit
0x0, isid 0x00023d000000
iscsid: > CHAP_A=5
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 12 bytes
iscsid: thread b7f5c518 schedule: delay 180 state 2
iscsid: send_pdu timer added 45 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 12 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c removed from actor_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 72 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 4 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: event_type: 4 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: detected iSCSI connection (handle 0xd2aa9000) error (1015)
state (2)
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed
iscsid: re-opening session 0 (reopen_cnt 13)
iscsid: in kstop_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: connection 0x0xd2aa9000 is stopped for recovery
iscsid: disconnecting conn 0xb7f5a478, fd 5
iscsid: flushing per-connection events
iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f5c4fc schedule: delay 60 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list
iscsid: thread b7f5c4fc wait some more
iscsid: event_type: 2 removing from the head:
0x0x95d9828:0x0x95d983c:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: connected local port 54098 to 66.173.145.126:3260
iscsid: thread b7f5c4fc delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: bound iSCSI connection (handle 0x0xd2aa9000) to session (handle
0x0xd1426668)
iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes
iscsid: thread b7f5c518 schedule: delay 60 state 2
iscsid: send_pdu timer added 15 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 160 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 1 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 1
iscsid: event_type: 1 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: in krecv_pdu_begin
iscsid: recv PDU began, pdu handle 0x0x95dd830
iscsid: in kread

iscsid: read 48 bytes of PDU header

iscsid: read 48 PDU header bytes, opcode 0x23, dlength 39, data
0xb7f5a4f8, max 8192
iscsid: in kread
iscsid: read 39 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 39 data, 3 pad
iscsid: login current stage 0, next stage 0, transit 0x0
iscsid: > AuthMethod=CHAP
iscsid: > TargetPortalGroupTag=1
iscsid: in krecv_pdu_end
iscsid: recv PDU finished for pdu handle 0x0x95dd830
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed

iscsid: login response status 0000

iscsid: sending login PDU with current stage 0, next stage 0, transit
0x0, isid 0x00023d000000
iscsid: > CHAP_A=5
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 12 bytes
iscsid: thread b7f5c518 schedule: delay 180 state 2
iscsid: send_pdu timer added 45 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 12 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c removed from actor_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 72 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 4 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: event_type: 4 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: detected iSCSI connection (handle 0xd2aa9000) error (1015)
state (2)
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed
iscsid: re-opening session 0 (reopen_cnt 12)
iscsid: in kstop_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: connection 0x0xd2aa9000 is stopped for recovery
iscsid: disconnecting conn 0xb7f5a478, fd 5
iscsid: flushing per-connection events
iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f5c4fc schedule: delay 60 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list
iscsid: thread b7f5c4fc wait some more
iscsid: event_type: 2 removing from the head:
0x0x95d9828:0x0x95d983c:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: connected local port 54099 to 66.173.145.126:3260
iscsid: thread b7f5c4fc delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: bound iSCSI connection (handle 0x0xd2aa9000) to session (handle
0x0xd1426668)
iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes
iscsid: thread b7f5c518 schedule: delay 60 state 2
iscsid: send_pdu timer added 15 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 160 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 1 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 1
iscsid: event_type: 1 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: in krecv_pdu_begin
iscsid: recv PDU began, pdu handle 0x0x95dd830
iscsid: in kread

iscsid: read 48 bytes of PDU header

iscsid: read 48 PDU header bytes, opcode 0x23, dlength 39, data
0xb7f5a4f8, max 8192
iscsid: in kread
iscsid: read 39 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 39 data, 3 pad
iscsid: login current stage 0, next stage 0, transit 0x0
iscsid: > AuthMethod=CHAP
iscsid: > TargetPortalGroupTag=1
iscsid: in krecv_pdu_end
iscsid: recv PDU finished for pdu handle 0x0x95dd830
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed

iscsid: login response status 0000

iscsid: sending login PDU with current stage 0, next stage 0, transit
0x0, isid 0x00023d000000
iscsid: > CHAP_A=5
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 12 bytes
iscsid: thread b7f5c518 schedule: delay 180 state 2
iscsid: send_pdu timer added 45 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 12 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c removed from actor_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 72 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 4 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: event_type: 4 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: detected iSCSI connection (handle 0xd2aa9000) error (1015)
state (2)
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed
iscsid: re-opening session 0 (reopen_cnt 11)
iscsid: in kstop_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: connection 0x0xd2aa9000 is stopped for recovery
iscsid: disconnecting conn 0xb7f5a478, fd 5
iscsid: flushing per-connection events
iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f5c4fc schedule: delay 60 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list
iscsid: thread b7f5c4fc wait some more
iscsid: event_type: 2 removing from the head:
0x0x95d9828:0x0x95d983c:0x0x95d983c:0x0x95dd828 elem 0x0x95d9828 length
20
iscsid: connected local port 54100 to 66.173.145.126:3260
iscsid: thread b7f5c4fc delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: bound iSCSI connection (handle 0x0xd2aa9000) to session (handle
0x0xd1426668)
iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes
iscsid: thread b7f5c518 schedule: delay 60 state 2
iscsid: send_pdu timer added 15 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c schedule: delay 0 state 2
iscsid: thread b7f7d44c removed from actor_list
iscsid: thread b7f7d44c removed from poll_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 160 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 1 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 1
iscsid: event_type: 1 removing from the head:
0x0x95d9828:0x0x95d9840:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: in krecv_pdu_begin
iscsid: recv PDU began, pdu handle 0x0x95dd830
iscsid: in kread

iscsid: read 48 bytes of PDU header

iscsid: read 48 PDU header bytes, opcode 0x23, dlength 39, data
0xb7f5a4f8, max 8192
iscsid: in kread
iscsid: read 39 bytes of PDU data
iscsid: finished reading login PDU, 48 hdr, 0 ah, 39 data, 3 pad
iscsid: login current stage 0, next stage 0, transit 0x0
iscsid: > AuthMethod=CHAP
iscsid: > TargetPortalGroupTag=1
iscsid: in krecv_pdu_end
iscsid: recv PDU finished for pdu handle 0x0x95dd830
iscsid: thread b7f5c518 delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: send_pdu timer removed

iscsid: login response status 0000

iscsid: sending login PDU with current stage 0, next stage 0, transit
0x0, isid 0x00023d000000
iscsid: > CHAP_A=5
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 12 bytes
iscsid: thread b7f5c518 schedule: delay 180 state 2
iscsid: send_pdu timer added 45 secs
iscsid: in kwritev

iscsid: wrote 48 bytes of PDU header

iscsid: in kwritev
iscsid: wrote 12 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: send PDU finished for conn (handle 0xd2aa9000)
iscsid: thread b7f7d44c removed from actor_list

iscsid: detected poll event 1

iscsid: in ctldev_handle
iscsid: in nl_read
iscsid: message real length is 72 bytes, recv_handle 0x95dd830
iscsid: in nlpayload_read
iscsid: event_type: 4 adding to the tail:
0x0x95d9828:0x0x95d9828:0x0x95d9840:0x0x95dd828 elem 0x0x95d9828 length
24
iscsid: thread b7f7d44c schedule: delay 0 state 2

[Wang Zhenyu]

On 2005.10.25 00:48:46 +0000, Albert Pauw wrote:
>
> > Hi Zhen,
> >
> > I am going to test this today and let you know if I encounter any
> > problems.
> >
> > Regards,
> >
> > Albert
>
> Hi Zhen,
>
> bad news. Although iscsiadm returns to the command probe, a "iscsid -d8
> -f" output shows the stuff at the bottom and keeps looping/trying.
>
> dmesg shows the following:
>
> SCSI subsystem initialized
> iscsi: registered transport (tcp)
> scsi0 : iSCSI Initiator over TCP/IP, v.0.3
> Vendor: Wasabi Model: WSB 1500i Rev: 0155
> Type: Direct-Access ANSI SCSI revision: 05
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
>

debug_tcp output?

[Albert Pauw]

[root@green ~]# iscsid -d8 -f
iscsid: IPC socket is listening...
iscsid: in ctldev_open
iscsid: created NETLINK_ISCSI socket...
iscsid: InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: no InitiatorAlias found in /etc/initiatorname.iscsi

iscsid: InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: InitiatorAlias=green

iscsid: version 0.3 variant (22-Apr-2005)
iscsid: in ktrans_list
iscsid: synced 1 transport(s)

iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1
iscsid: detected poll event 1

iscsid: updating defaults from '/etc/iscsid.conf'
iscsid: updated 'node.startup', 'manual' => 'manual'
iscsid: updated 'node.session.timeo.replacement_timeout', '0' => '0'
iscsid: updated 'node.session.err_timeo.abort_timeout', '10' => '10'
iscsid: updated 'node.session.err_timeo.reset_timeout', '30' => '30'
iscsid: updated 'node.session.iscsi.InitialR2T', 'No' => 'No'
iscsid: updated 'node.session.iscsi.ImmediateData', 'Yes' => 'Yes'
iscsid: updated 'node.session.iscsi.FirstBurstLength', '262144' =>
'262144'
iscsid: updated 'node.session.iscsi.MaxBurstLength', '16776192' =>
'16776192'
iscsid: updated 'node.session.iscsi.DefaultTime2Wait', '0' => '0'
iscsid: updated 'node.session.iscsi.DefaultTime2Retain', '0' => '0'
iscsid: updated 'node.session.iscsi.MaxConnections', '1' => '1'
iscsid: searching for key
'66.173.145.126:3260#66.173.145.126:3260,1#iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0'
iscsid: in ktrans_list
iscsid: thread b7fc444c schedule: delay 0 state 2
iscsid: authentication setup complete...
iscsid: resolved 66.173.145.126 to 66.173.145.126

iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:

0x0x9f92828:0x0x9f92828:0x0x9f9283c:0x0x9f96828 elem 0x0x9f92828 length
20
iscsid: thread b7fc444c schedule: delay 0 state 1
iscsid: thread b7fa34fc schedule: delay 60 state 2

iscsid: event_type: 2 removing from the head:

0x0x9f92828:0x0x9f9283c:0x0x9f9283c:0x0x9f96828 elem 0x0x9f92828 length
20
iscsid: connected local port 47889 to 66.173.145.126:3260
iscsid: thread b7fa34fc delete: state 0

iscsid: deleting a scheduled/waiting thread!

iscsid: in kcreate_session

iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: created new iSCSI session, handle 0x0xd451fe68
iscsid: in kcreate_conn

iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: created new iSCSI connection, handle 0x0xd571f400

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: bound iSCSI connection (handle 0x0xd571f400) to session (handle
0x0xd451fe68)

iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes

iscsid: thread b7fa3518 schedule: delay 60 state 2

iscsid: send_pdu timer added 15 secs
iscsid: in kwritev
iscsid: wrote 48 bytes of PDU header
iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: send PDU finished for conn (handle 0xd571f400)
iscsid: thread b7fc444c schedule: delay 0 state 2
iscsid: thread b7fc444c removed from actor_list
iscsid: thread b7fc444c removed from poll_list
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fc444c removed from actor_list
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 wait some more
iscsid: thread b7fa3518 was scheduled at 109:60, curtime 170 q_forw
0x8062ea8 &pend_list 0x8062ea8
iscsid: thread b7fa3518 now in actor_list
iscsid: event_type: 3 adding to the tail:
0x0x9f92828:0x0x9f92828:0x0x9f9283c:0x0x9f96828 elem 0x0x9f92828 length
20
iscsid: thread b7fc444c schedule: delay 0 state 2
iscsid: send_pdu timer timedout!
iscsid: thread b7fa3518 removed from actor_list
iscsid: thread b7fc444c removed from poll_list
iscsid: event_type: 3 removing from the head:
0x0x9f92828:0x0x9f9283c:0x0x9f9283c:0x0x9f96828 elem 0x0x9f92828 length
20
iscsid: disconnecting conn 0xb7fa1478, fd 6
iscsid: conn_timer popped at IN_LOGIN
iscsid: in kdestroy_conn

iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: in kdestroy_session

iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: thread b7fc444c delete: state 2
iscsid: thread b7fc444c removed from actor_list

[Wang Zhenyu]

On 2005.10.25 00:48:46 +0000, Albert Pauw wrote:
>

> > Hi Zhen,
> >
> > I am going to test this today and let you know if I encounter any
> > problems.
> >
> > Regards,
> >
> > Albert
>
> Hi Zhen,
>
> bad news. Although iscsiadm returns to the command probe, a "iscsid -d8
> -f" output shows the stuff at the bottom and keeps looping/trying.
>
> dmesg shows the following:
>
> SCSI subsystem initialized
> iscsi: registered transport (tcp)
> scsi0 : iSCSI Initiator over TCP/IP, v.0.3
> Vendor: Wasabi Model: WSB 1500i Rev: 0155
> Type: Direct-Access ANSI SCSI revision: 05
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
> iscsi0: detected conn error (1015)
>
>

debug_tcp output?

[Wang Zhenyu]

This show another issue, or not?
I wanna see kernel log with DEBUG_TCP, as you sent that before.

[Albert Pauw]

Sorry, I don't get much info now:

from dmesg:

iscsi: registered transport (tcp)
scsi2 : iSCSI Initiator over TCP/IP, v.0.3

tcp: sendhdr 48 bytes, sent 0 res 48
tcp: sendpage: 180 bytes, sent 0 left 180 sent 0 res 180

and from the iscsiadm command:

[root@green ~]# iscsiadm -m node -r a1d16f --login
iscsiadm: iscsid reported error (11 - iSCSI PDU timed out)

Albert

[Albert Pauw]

Hi Zhen,

here is again the output of iscsid -d8 -f

iscsid: thread b7f9b44c schedule: delay 0 state 2

iscsid: authentication setup complete...
iscsid: resolved 66.173.145.126 to 66.173.145.126
iscsid: set TCP recv window size to 524288, actually got 262142
iscsid: set TCP send window size to 524288, actually got 262142
iscsid: connecting to 66.173.145.126:3260
iscsid: event_type: 2 adding to the tail:

0x0x93d6828:0x0x93d6828:0x0x93d683c:0x0x93da828 elem 0x0x93d6828 length
20
iscsid: thread b7f9b44c schedule: delay 0 state 1
iscsid: thread b7f7a4fc schedule: delay 60 state 2

iscsid: event_type: 2 removing from the head:

0x0x93d6828:0x0x93d683c:0x0x93d683c:0x0x93da828 elem 0x0x93d6828 length
20
iscsid: connected local port 54720 to 66.173.145.126:3260
iscsid: thread b7f7a4fc delete: state 0

iscsid: deleting a scheduled/waiting thread!
iscsid: in kcreate_session
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: created new iSCSI session, handle 0x0xd0392668

iscsid: in kcreate_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: created new iSCSI connection, handle 0x0xd0392800

iscsid: in kbind_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: bound iSCSI connection (handle 0x0xd0392800) to session (handle
0x0xd0392668)

iscsid: sending login PDU with current stage 0, next stage 1, transit
0x80, isid 0x00023d000000
iscsid: > InitiatorName=iqn.2005-06.net.homeunix.pauw:green
iscsid: > InitiatorAlias=green
iscsid: >
TargetName=iqn.2000-05.com.wasabisystems.storagebuilder:wasabi1-0
iscsid: > SessionType=Normal
iscsid: > AuthMethod=CHAP,None
iscsid: in ksend_pdu_begin
iscsid: send PDU began for hdr 48 bytes and data 180 bytes

iscsid: thread b7f7a518 schedule: delay 60 state 2

iscsid: send_pdu timer added 15 secs
iscsid: in kwritev
iscsid: wrote 48 bytes of PDU header
iscsid: in kwritev
iscsid: wrote 180 bytes of PDU data
iscsid: in ksend_pdu_end
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: send PDU finished for conn (handle 0xd0392800)
iscsid: thread b7f9b44c schedule: delay 0 state 2
iscsid: thread b7f9b44c removed from actor_list
iscsid: thread b7f9b44c removed from poll_list
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f9b44c removed from actor_list
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 wait some more
iscsid: thread b7f7a518 was scheduled at 112:60, curtime 173 q_forw
0x8062ea8 &pend_list 0x8062ea8
iscsid: thread b7f7a518 now in actor_list

iscsid: event_type: 3 adding to the tail:

0x0x93d6828:0x0x93d6828:0x0x93d683c:0x0x93da828 elem 0x0x93d6828 length
20
iscsid: thread b7f9b44c schedule: delay 0 state 2
iscsid: send_pdu timer timedout!
iscsid: thread b7f7a518 removed from actor_list
iscsid: thread b7f9b44c removed from poll_list

iscsid: event_type: 3 removing from the head:

0x0x93d6828:0x0x93d683c:0x0x93d683c:0x0x93da828 elem 0x0x93d6828 length
20
iscsid: disconnecting conn 0xb7f78478, fd 6

iscsid: conn_timer popped at IN_LOGIN
iscsid: in kdestroy_conn
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read
iscsid: in kdestroy_session
iscsid: in __kipc_call
iscsid: in kwritev
iscsid: in nlpayload_read
iscsid: in nlpayload_read

iscsid: thread b7f9b44c delete: state 2
iscsid: thread b7f9b44c removed from actor_list

Both target and initiator forced to DataDigest CRC32C.

That's all I can give I am afraid.

Albert

[Albert Pauw]

Because I changed provider it seems I can't login the target anymore.
Sorry about the messing up.

If I got it sorted out I will try out your patch again.

Albert

[Albert Pauw]

I managed to get it sorted out ;-)

Here is the output of dmesg:

SCSI subsystem initialized
iscsi: registered transport (tcp)

scsi0 : iSCSI Initiator over TCP/IP, v.0.3

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: sendpage: 560 bytes, sent 0 left 560 sent 0 res 560
tcp: in 420 bytes
tcp: opcode 0x23 offset 48 copy 372 ahslen 0 datalen 371
tcp: data_recv offset 48 copy 372
tcp: tcp_copy 371 bytes at offset 48 copied 0
tcp: f, processed 420 from out of 420 padding 1

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: in 88 bytes
tcp: opcode 0x25 offset 48 copy 40 ahslen 0 datalen 36
tcp: data_recv offset 48 copy 40
tcp: ctask_copy 36 bytes at offset 48 copied 0
tcp: rx digest 0xd88a7517
tcp: f, processed 84 from out of 88 padding 0
tcp: continue to process 4 bytes
tcp: extra data_recv offset 84 copy 4
tcp: iscsi_tcp: data digest match!0xd88a7517 == 0xd88a7517
tcp: f, processed 88 from out of 88 padding 0
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: in 120 bytes
tcp: opcode 0x25 offset 48 copy 72 ahslen 0 datalen 66
tcp: data_recv offset 48 copy 72
tcp: ctask_copy 66 bytes at offset 48 copied 0
tcp: padding -> 2
tcp: rx digest 0x4448b661
tcp: f, processed 116 from out of 120 padding 2
tcp: continue to process 4 bytes
tcp: extra data_recv offset 116 copy 4
tcp: iscsi_tcp: data digest match!0x4448b661 == 0x4448b661
tcp: f, processed 120 from out of 120 padding 2
tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0

Vendor: Wasabi Model: WSB 1500i Rev: 0155
Type: Direct-Access ANSI SCSI revision: 05

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: in 68 bytes
tcp: opcode 0x25 offset 48 copy 20 ahslen 0 datalen 16
tcp: data_recv offset 48 copy 20
tcp: ctask_copy 16 bytes at offset 48 copied 0
tcp: rx digest 0xc10d2f33
tcp: f, processed 64 from out of 68 padding 0

tcp: continue to process 4 bytes

tcp: extra data_recv offset 64 copy 4
tcp: iscsi_tcp: data digest match!0xc10d2f33 == 0xc10d2f33
tcp: f, processed 68 from out of 68 padding 0

tcp: in 48 bytes
tcp: opcode 0x21 offset 48 copy 0 ahslen 0 datalen 0
tcp: f, processed 48 from out of 48 padding 0

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: in 72 bytes
tcp: opcode 0x21 offset 48 copy 24 ahslen 0 datalen 20
tcp: data_recv offset 48 copy 24
tcp: tcp_copy 20 bytes at offset 48 copied 0

tcp: rx digest 0x0

tcp: f, processed 68 from out of 72 padding 0
tcp: continue to process 4 bytes

tcp: extra data_recv offset 68 copy 4
tcp: iscsi_tcp: data digest error!0x8c823931 != 0x0

iscsi0: detected conn error (1015)

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: sendpage: 552 bytes, sent 0 left 552 sent 560 res 552
tcp: in 420 bytes
tcp: opcode 0x23 offset 48 copy 372 ahslen 0 datalen 371
tcp: data_recv offset 48 copy 372
tcp: tcp_copy 371 bytes at offset 48 copied 0
tcp: padding -> 1
tcp: rx digest 0x527d5351
tcp: f, processed 420 from out of 420 padding 1

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: in 72 bytes
tcp: extra data_recv offset 0 copy 72
tcp: iscsi_tcp: data digest error!0x2008021 != 0x527d5351

iscsi0: detected conn error (1015)

tcp: sendhdr 48 bytes, sent 0 res 48

tcp: sendpage: 552 bytes, sent 0 left 552 sent 1112 res 552
tcp: in 420 bytes
tcp: opcode 0x23 offset 48 copy 372 ahslen 0 datalen 371
tcp: data_recv offset 48 copy 372
tcp: tcp_copy 371 bytes at offset 48 copied 0
tcp: padding -> 1
tcp: rx digest 0x527d5351
tcp: f, processed 420 from out of 420 padding 1

Still no partition table there :-(

Albert

[Wang Zhenyu]

obviously I don't do digest update for sense data. thanks for showing this!
I'll send a patch later.

zhen

[Wang Zhenyu]

Here's the updated patch, which remove the constrains only for data-in pdu,
and do digest update for other data recv.

Signed-off-by: Wang Zhenyu <zhenyu...@intel.com>
---

--- kernel/iscsi_tcp.c.orig 2005-10-25 15:28:14.000000000 +0800
+++ kernel/iscsi_tcp.c 2005-10-26 10:24:21.000000000 +0800
@@ -905,11 +905,20 @@ partial_sg_digest_update(struct iscsi_co
crypto_digest_update(conn->data_rx_tfm, &temp, 1);
}

+static void
+iscsi_recv_digest_update(struct iscsi_conn *conn, char* buf, int len)
+{
+ struct scatterlist tmp;
+
+ sg_init_one(&tmp, buf, len);
+ crypto_digest_update(conn->data_rx_tfm, &tmp, 1);
+}
+
static int iscsi_scsi_data_in(struct iscsi_conn *conn)
{
struct iscsi_cmd_task *ctask = conn->in.ctask;
struct scsi_cmnd *sc = ctask->sc;
- struct scatterlist tmp, *sg;
+ struct scatterlist *sg;
int i, offset, rc = 0;

BUG_ON((void*)ctask != sc->SCp.ptr);
@@ -923,10 +932,8 @@ static int iscsi_scsi_data_in(struct isc
sc->request_bufflen, ctask->data_offset);
if (rc == -EAGAIN)
return rc;
- if (conn->datadgst_en) {
- sg_init_one(&tmp, sc->request_buffer, i);
- crypto_digest_update(conn->data_rx_tfm, &tmp, 1);
- }
+ if (conn->datadgst_en)
+ iscsi_recv_digest_update(conn, sc->request_buffer, i);
rc = 0;
goto done;
}
@@ -1020,6 +1027,9 @@ iscsi_data_recv(struct iscsi_conn *conn)
conn->in.hdr = &conn->hdr;
conn->senselen = (conn->data[0] << 8) | conn->data[1];
rc = iscsi_cmd_rsp(conn, conn->in.ctask);
+ if (!rc && conn->datadgst_en)
+ iscsi_recv_digest_update(conn, conn->data,
+ conn->in.datalen);
}
break;
case ISCSI_OP_TEXT_RSP:
@@ -1044,6 +1054,11 @@ iscsi_data_recv(struct iscsi_conn *conn)
rc = iscsi_recv_pdu(iscsi_handle(conn), conn->in.hdr,
conn->data, conn->in.datalen);

+ if (!rc && conn->datadgst_en &&
+ conn->in.opcode != ISCSI_OP_LOGIN_RSP)
+ iscsi_recv_digest_update(conn, conn->data,
+ conn->in.datalen);
+
if (mtask && conn->login_mtask != mtask) {
spin_lock(&session->lock);
__kfifo_put(session->mgmtpool.queue, (void*)&mtask,
@@ -1052,6 +1067,8 @@ iscsi_data_recv(struct iscsi_conn *conn)
}
}
break;
+ case ISCSI_OP_ASYNC_EVENT:
+ case ISCSI_OP_REJECT:
default:
BUG_ON(1);
}
@@ -1113,8 +1130,7 @@ more:

*/
rc = iscsi_hdr_recv(conn);
if (!rc && conn->in.datalen) {
- if (conn->datadgst_en &&
- conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {
+ if (conn->datadgst_en) {
BUG_ON(!conn->data_rx_tfm);
crypto_digest_init(conn->data_rx_tfm);
}

@@ -1126,26 +1142,24 @@ more:

@@ -1166,8 +1180,7 @@ more:

[Albert Pauw]

Hi Zhen,

thanks, could you send me the patch, copy and paste doesn't work to
well with patches.

Albert

[Wang Zhenyu]

On 2005.10.26 10:28:14 +0000, Albert Pauw wrote:
>
> Hi Zhen,

> it works! I got the partition table intact, created a fs on one of the
> partitions and save some data on it.
> After that I unmounted, logged out and back in again, mounted the partition
> and the data was there and in tact.
> Seems to work fine!
> One noticable thing is that it is slower (client = P-III 700), which is
> probably from the overhead of calculating the CRC32 checksum.
> That's where a TOE steps in!
> Thanks for the fix, I just carry on testing. Are there any particular
> parameters you want me to test with the Wasabi target?
> Albert

ok, just send this to the list.


> Wang Zhenyu wrote:

> ok, attached.
>
> zhen
>
> _______________________________________________________________________

[Albert Pauw]

Just wait for the patch to be put in svn. I was testing and while
copying files to the target, using DataDigest CRC32C, eventually I get
errors and the target disconnects forcefully. Although I can't connect
anymore at the moment it felt like buffers. Unfortunately I did testing
with the debug option off. So for the moment I can only give the output
of /var/log/messages.

Albert

Oct 26 16:53:01 green kernel: iscsi: registered transport (tcp)
Oct 26 16:53:01 green iscsid: iSCSI logger with pid=4994 started!
Oct 26 16:53:01 green open-iscsi: iscsid startup succeeded
Oct 26 16:53:02 green iscsid: iSCSI daemon with pid=4995 started!
Oct 26 16:53:02 green iscsid: version 0.3 variant (22-Apr-2005)
Oct 26 16:53:22 green kernel: scsi0 : iSCSI Initiator over TCP/IP,
v.0.3
Oct 26 16:53:24 green kernel: Vendor: Wasabi Model: WSB 1500i
Rev: 0155
Oct 26 16:53:24 green kernel: Type: Direct-Access
ANSI SCSI revision: 05
Oct 26 16:53:24 green scsi.agent[5053]: disk at
/devices/platform/host0/target0:0:0/0:0:0:0
Oct 26 16:53:24 green kernel: SCSI device sda: 919595008 512-byte hdwr
sectors (470833 MB)
Oct 26 16:53:25 green kernel: SCSI device sda: drive cache: write back
Oct 26 16:53:25 green kernel: SCSI device sda: 919595008 512-byte hdwr
sectors (470833 MB)
Oct 26 16:53:25 green iscsid: connection0:0 is operational now
Oct 26 16:53:25 green kernel: SCSI device sda: drive cache: write back
Oct 26 16:53:25 green kernel: sda: sda1 sda2 sda3 sda4
Oct 26 16:53:25 green kernel: Attached scsi disk sda at scsi0, channel

0, id 0, lun 0

Oct 26 16:53:46 green kernel: cfq: depth 4 reached, tagging now on
Oct 26 16:54:51 green ntpd[3942]: kernel time sync enabled 0001
Oct 26 16:55:51 green kernel: iscsi0: detected conn error (1005)
Oct 26 16:55:51 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1005) state (3)
Oct 26 16:55:52 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:52 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:53 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:53 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:54 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:54 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:55 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:55 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:56 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:56 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:57 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:57 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:58 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:58 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:55:59 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:55:59 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:00 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:00 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:01 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:01 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:02 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:02 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:03 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:03 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:04 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:04 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:05 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:05 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:06 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:06 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:07 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:07 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:08 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:08 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:09 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:09 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:10 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:10 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:11 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:11 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:12 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:12 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:13 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:13 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:14 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:14 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:15 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:15 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:16 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:16 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:17 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:17 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:18 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:18 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:18 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:19 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:19 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:20 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:20 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:21 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:21 green kernel: iscsi0: detected conn error (1015)
Oct 26 16:56:22 green kernel: scsi: Device offlined - not ready after
error recovery: host 0 channel 0 id 0 lun 0
Oct 26 16:56:22 green last message repeated 7 times
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659759844
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to offline
device
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 49421
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 49492
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659661032
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 1
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659662084
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659661554
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 262
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659661548
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 259
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to offline
device
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 260
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659661034
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 2
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659759336
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 49153
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: SCSI error : <0 0 0 0> return code =
0x6000000
Oct 26 16:56:22 green kernel: end_request: I/O error, dev sda, sector
659759338
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 49154
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to offline
device
Oct 26 16:56:22 green kernel: Buffer I/O error on device sda4, logical
block 49155
Oct 26 16:56:22 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to offline
device
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to offline
device
Oct 26 16:56:22 green kernel: conn_destroy(): host_busy 0 host_failed 0
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to device
being removed
Oct 26 16:56:22 green kernel: scsi0 (0:0): rejecting I/O to device
being removed
Oct 26 16:56:22 green kernel: EXT2-fs error (device sda4):
ext2_get_inode: unable to read inode block - inode=2, block=261
Oct 26 16:56:22 green kernel: Synchronizing SCSI cache for disk sda:
Oct 26 16:56:22 green kernel: iscsi_tcp: cmd 0x35 is not queued (5)
Oct 26 16:56:22 green last message repeated 2 times
Oct 26 16:56:22 green kernel: FAILED
Oct 26 16:56:22 green kernel: status = 0, message = 00, host = 1,
driver = 08
Oct 26 16:56:22 green kernel: <6>sd: Current: sense key: Not Ready
Oct 26 16:56:22 green kernel: Additional sense: Logical unit
communication failure
Oct 26 16:56:22 green iscsid: detected iSCSI connection (handle
0xe60eac00) error (1015) state (2)
Oct 26 16:56:27 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:27 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:27 green kernel: printk: 3 messages suppressed.
Oct 26 16:56:27 green kernel: Buffer I/O error on device sda4, logical
block 1
Oct 26 16:56:27 green kernel: lost page write due to I/O error on sda4
Oct 26 16:56:27 green kernel: EXT2-fs error (device sda4):
read_inode_bitmap: Cannot read inode bitmap - block_group = 1,
inode_bitmap = 8452
Oct 26 16:56:27 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:27 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:27 green kernel: EXT2-fs error (device sda4):
read_inode_bitmap: Cannot read inode bitmap - block_group = 3,
inode_bitmap = 24836
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: EXT2-fs error (device sda4):
ext2_get_inode: unable to read inode block - inode=11, block=262
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: EXT2-fs error (device sda4):
ext2_get_inode: unable to read inode block - inode=12, block=262
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:56:28 green kernel: EXT2-fs error (device sda4):
ext2_get_inode: unable to read inode block - inode=12097, block=49155
Oct 26 16:57:01 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:57:01 green kernel: scsi0 (0:0): rejecting I/O to dead device
Oct 26 16:57:01 green kernel: printk: 4 messages suppressed.
Oct 26 16:57:01 green kernel: Buffer I/O error on device sda4, logical
block 1
Oct 26 16:57:01 green kernel: lost page write due to I/O error on sda4
Oct 26 16:57:01 green kernel: EXT2-fs error (device sda4):
ext2_get_inode: unable to read inode block - inode=2, block=261
Oct 26 16:57:02 green kernel: KERNEL: assertion

[Albert Pauw]

Haven't been able to work on the Wasabi target (which is offline now)
but tried iscsi-target (last release) with DataDigest and get more or
less the same result.

Albert

P.S. I get the errors when the buffers are flushed, which I forced in
this case with a sync.

/var/log/messages (with iscsi_tcp debug on):

Oct 27 09:42:00 green kernel: SCSI subsystem initialized
Oct 27 09:42:00 green kernel: iscsi: registered transport (tcp)
Oct 27 09:42:00 green iscsid: iSCSI logger with pid=4604 started!
Oct 27 09:42:01 green open-iscsi: iscsid startup succeeded
Oct 27 09:42:01 green iscsid: iSCSI daemon with pid=4605 started!
Oct 27 09:42:01 green iscsid: version 0.3 variant (22-Apr-2005)
Oct 27 09:42:46 green kernel: iSCSI Enterprise Target Software -
version 0.4.13
Oct 27 09:42:46 green kernel: iotype_init(90) register fileio
Oct 27 09:42:46 green kernel: iotype_init(90) register nullio
Oct 27 09:42:46 green iscsi-target: ietd startup succeeded
Oct 27 09:42:46 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 20 1 1 1 0 3 1
Oct 27 09:42:46 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 20 1 1 1 0 3 3
Oct 27 09:42:50 green kernel: scsi1 : iSCSI Initiator over TCP/IP,
v.0.3
Oct 27 09:42:50 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:42:51 green kernel: Vendor: IET Model: VIRTUAL-DISK
Rev: 0
Oct 27 09:42:51 green kernel: Type: Direct-Access
ANSI SCSI revision: 04
Oct 27 09:42:51 green scsi.agent[4747]: disk at
/devices/platform/host1/target1:0:0/1:0:0:0
Oct 27 09:42:51 green kernel: SCSI device sda: 20480 512-byte hdwr
sectors (10 MB)
Oct 27 09:42:51 green kernel: SCSI device sda: drive cache: write back
Oct 27 09:42:51 green kernel: SCSI device sda: 20480 512-byte hdwr
sectors (10 MB)
Oct 27 09:42:51 green kernel: SCSI device sda: drive cache: write back
Oct 27 09:42:51 green kernel: sda: sda1
Oct 27 09:42:51 green kernel: Attached scsi disk sda at scsi1, channel

0, id 0, lun 0

Oct 27 09:42:53 green iscsid: connection1:0 is operational now
Oct 27 09:43:06 green kernel: cfq: depth 4 reached, tagging now on
Oct 27 09:43:56 green kernel: iscsi1: detected conn error (1011)
Oct 27 09:43:56 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:43:57 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1011) state (3)
Oct 27 09:43:57 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:44:26 green kernel: iscsi1: detected conn error (1015)
Oct 27 09:44:26 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:44:27 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1015) state (3)
Oct 27 09:44:27 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:44:36 green kernel: iscsi1: detected conn error (1015)
Oct 27 09:44:36 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:44:37 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1015) state (3)
Oct 27 09:44:37 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:44:46 green kernel: iscsi1: detected conn error (1011)
Oct 27 09:44:46 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:44:47 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1011) state (3)
Oct 27 09:44:47 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:44:56 green kernel: iscsi1: detected conn error (1015)
Oct 27 09:44:56 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:44:57 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1015) state (3)
Oct 27 09:44:57 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:45:06 green kernel: iscsi1: detected conn error (1015)
Oct 27 09:45:06 green kernel: sess_param(173) 1 1 1 8192 8192 262144
65536 2 0 1 1 1 0 2 2
Oct 27 09:45:07 green iscsid: detected iSCSI connection (handle
0xd3d19c00) error (1015) state (3)
Oct 27 09:45:07 green iscsid: connection1:0 is operational after
recovery (1 attempts)
Oct 27 09:45:16 green kernel: scsi: Device offlined - not ready after
error recovery: host 1 channel 0 id 0 lun 0
Oct 27 09:45:16 green kernel: scsi: Device offlined - not ready after
error recovery: host 1 channel 0 id 0 lun 0
Oct 27 09:45:16 green kernel: SCSI error : <1 0 0 0> return code =
0x6000000
Oct 27 09:45:16 green kernel: end_request: I/O error, dev sda, sector
13334
Oct 27 09:45:16 green kernel: scsi1 (0:0): rejecting I/O to offline
device
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 6729
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: scsi1 (0:0): rejecting I/O to offline
device
Oct 27 09:45:16 green kernel: scsi1 (0:0): rejecting I/O to offline
device
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 231
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: scsi1 (0:0): rejecting I/O to offline
device
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 6943
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 6961
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 6996
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 7084
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 7145
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 7168
Oct 27 09:45:16 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:16 green kernel: Buffer I/O error on device sda1, logical
block 7209
Oct 27 09:45:17 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:17 green kernel: Buffer I/O error on device sda1, logical
block 7250
Oct 27 09:45:17 green kernel: lost page write due to I/O error on sda1
Oct 27 09:45:17 green kernel: scsi1 (0:0): rejecting I/O to offline
device
Oct 27 09:45:17 green last message repeated 15 times
Oct 27 09:45:17 green kernel: SCSI error : <1 0 0 0> return code =
0x6000000
Oct 27 09:45:17 green kernel: end_request: I/O error, dev sda, sector
13584
Oct 27 09:45:17 green kernel: scsi1 (0:0): rejecting I/O to offline
device

[Levine, Daniel J.]

This may be very similar to my issue on the V-Switch 3000. I also get
this message:

scsi1: detected conn error (1011)

And eventually dies a horrible death as a device like yours.

I cause mine to happen several different ways:

1. Interrupting bonnie++ when it's doing the intense block writing and
re-writing.
2. When bonnie++ is transitioning to the file oriented stuff from the
block reading. (theory is there's a flush at the transition)

I'm not sure if it's related, but I often like to improve performance on
bonnie++ by using a command like:

blockdev --setra 16384 /dev/sXX

This may intensify the situation. I'll help you guys test solutions to
this issue when you're ready. At the moment, this is probably my
biggest issue with open-iscsi.

Daniel J. Levine
A3C4 Section Supervisor
Air Defense Systems Department
Johns Hopkins University Applied Physics Laboratory
Phone: (443) 778-3952 (240) 228-3952

[Albert Pauw]

> 1. Interrupting bonnie++ when it's doing the intense block writing and
> re-writing.
> 2. When bonnie++ is transitioning to the file oriented stuff from the
> block reading. (theory is there's a flush at the transition)

Noticed that too before, but I related it to testing the target
(Wasabi) over the internet, seems this is not the cause. And I noticed
it without the DataDigest set to CRC32C. Are you using that in your
target?

Albert

[Albert Pauw]

Found some more errors in the log of the target (i.e. the Wasabi
target) which may be interesting (Zhen?). Just before the target hung
up I saw this:

Oct 26 10:47:54 wasabi1 utarget_fsdisk: thread
main:target.c:kq_conn:1574: ***ERROR*** Data CRC failure. Calculated
0x8e7cbea2, read 0x7d3c7e02 (Ethereal numbers 71365d45 and be344240
respectively)
Oct 26 10:47:54 wasabi1 utarget_fsdisk: thread
main:target.c:kq_conn:1574: ***ERROR*** Data CRC failure. Calculated
0x8f78d56e, read 0x4979f680 (Ethereal numbers f11ea276 and 82966701
respectively)
Oct 26 10:47:55 wasabi1 utarget_fsdisk: thread
main:target.c:kq_conn:1574: ***ERROR*** Data CRC failure. Calculated
0x0cdcfff5, read 0xbed1fd85 (Ethereal numbers 303349af and 6d83afa1
respectively)

I can't relate it to the exact moment when open-iscsi gave up. But it
looks like the CRC is still not completely calculated correctly.

Albert

[Levine, Daniel J.]

I must admit, my target is commercial hardware from Sanrad. I'm not
intentionally setting any options in the iSCSI initiator or target to
add CRC checking.

Is there a command I should run to find out the mode I'm running in
implicitly?

Perhaps I just need to do an:

iscsiadm -m node --record XXXX

to get the details of the connection?

Daniel J. Levine
A3C4 Section Supervisor
Air Defense Systems Department
Johns Hopkins University Applied Physics Laboratory
Phone: (443) 778-3952 (240) 228-3952

-----Original Message-----
From: open-...@googlegroups.com [mailto:open-...@googlegroups.com]
On Behalf Of Albert Pauw
Sent: Thursday, October 27, 2005 9:34 AM
To: open-iscsi
Subject: Re: DataDigest corruption with Wasabi target

[Dmitry Yusupov]

Guys,

just would like to point out. Error "detected conn error (1011)" is most
likely points to the interoperability issue.

It could be:

a) interoperability issue on target side

b) interoperability issue on initiator side

To find out, we need ethereal traces which covers:

a) session establishment

b) the moment when error happen

Thanks!
Dima

[Levine, Daniel J.]

Albert,

Can you provide those traces? My security situation makes this
difficult.

[Albert Pauw]

> Perhaps I just need to do an:

> iscsiadm -m node --record XXXX

> to get the details of the connection?

On the bottom of the list you get:

node.conn[0].iscsi.HeaderDigest = None,CRC32C
node.conn[0].iscsi.DataDigest = None <- would show CRC32C when set
node.conn[0].iscsi.IFMarker = No
node.conn[0].iscsi.OFMarker = No

Albert

[Albert Pauw]

> Albert,

> Can you provide those traces? My security situation makes this
> difficult.

Once I can connect to the Wasabi target I will do that. It will be a
lot of data :-)

Albert

[Levine, Daniel J.]

Albert,

Data digest for me = None

Daniel J. Levine
A3C4 Section Supervisor
Air Defense Systems Department
Johns Hopkins University Applied Physics Laboratory
Phone: (443) 778-3952 (240) 228-3952

-----Original Message-----
From: open-...@googlegroups.com [mailto:open-...@googlegroups.com]
On Behalf Of Albert Pauw
Sent: Thursday, October 27, 2005 11:06 AM
To: open-iscsi
Subject: Re: DataDigest corruption with Wasabi target

[Wang Zhenyu]

Here's update patch against r431. I tested it with 2G bonnie job on iet target.
That (1005) error may be caused by our unimplemented REJECT and ASYNC_EVENT.

Signed-off-by: Wang Zhenyu <zhenyu...@intel.com>
---

--- kernel/iscsi_tcp.c.orig 2005-10-09 23:22:45.000000000 +0800
+++ kernel/iscsi_tcp.c 2005-10-28 11:35:09.000000000 +0800
@@ -903,11 +903,20 @@ partial_sg_digest_update(struct iscsi_co

crypto_digest_update(conn->data_rx_tfm, &temp, 1);
}

+static void
+iscsi_recv_digest_update(struct iscsi_conn *conn, char* buf, int len)
+{
+ struct scatterlist tmp;
+
+ sg_init_one(&tmp, buf, len);
+ crypto_digest_update(conn->data_rx_tfm, &tmp, 1);
+}
+
static int iscsi_scsi_data_in(struct iscsi_conn *conn)
{
struct iscsi_cmd_task *ctask = conn->in.ctask;
struct scsi_cmnd *sc = ctask->sc;
- struct scatterlist tmp, *sg;
+ struct scatterlist *sg;
int i, offset, rc = 0;

BUG_ON((void*)ctask != sc->SCp.ptr);

@@ -921,10 +930,8 @@ static int iscsi_scsi_data_in(struct isc

sc->request_bufflen, ctask->data_offset);
if (rc == -EAGAIN)
return rc;
- if (conn->datadgst_en) {
- sg_init_one(&tmp, sc->request_buffer, i);
- crypto_digest_update(conn->data_rx_tfm, &tmp, 1);
- }
+ if (conn->datadgst_en)
+ iscsi_recv_digest_update(conn, sc->request_buffer, i);
rc = 0;
goto done;
}

@@ -1018,6 +1025,9 @@ iscsi_data_recv(struct iscsi_conn *conn)

conn->in.hdr = &conn->hdr;
conn->senselen = (conn->data[0] << 8) | conn->data[1];
rc = iscsi_cmd_rsp(conn, conn->in.ctask);
+ if (!rc && conn->datadgst_en)
+ iscsi_recv_digest_update(conn, conn->data,
+ conn->in.datalen);
}
break;
case ISCSI_OP_TEXT_RSP:

@@ -1042,6 +1052,11 @@ iscsi_data_recv(struct iscsi_conn *conn)

rc = iscsi_recv_pdu(iscsi_handle(conn), conn->in.hdr,
conn->data, conn->in.datalen);

+ if (!rc && conn->datadgst_en &&
+ conn->in.opcode != ISCSI_OP_LOGIN_RSP)
+ iscsi_recv_digest_update(conn, conn->data,
+ conn->in.datalen);
+
if (mtask && conn->login_mtask != mtask) {
spin_lock(&session->lock);
__kfifo_put(session->mgmtpool.queue, (void*)&mtask,

@@ -1050,6 +1065,8 @@ iscsi_data_recv(struct iscsi_conn *conn)

}
}
break;
+ case ISCSI_OP_ASYNC_EVENT:
+ case ISCSI_OP_REJECT:
default:
BUG_ON(1);
}

@@ -1112,7 +1129,7 @@ more:

rc = iscsi_hdr_recv(conn);
if (!rc && conn->in.datalen) {

if (conn->datadgst_en &&
- conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {

+ conn->in.opcode != ISCSI_OP_LOGIN_RSP) {
BUG_ON(!conn->data_rx_tfm);
crypto_digest_init(conn->data_rx_tfm);
}
@@ -1124,26 +1141,24 @@ more:

@@ -1165,7 +1180,7 @@ more:

conn->in.copy -= conn->in.padding;
conn->in.offset += conn->in.padding;

if (conn->datadgst_en &&
- conn->in.opcode == ISCSI_OP_SCSI_DATA_IN) {

+ conn->in.opcode != ISCSI_OP_LOGIN_RSP) {

[Alex Aizman]

Applied, r432.

Thanks for the perseverance!

> ------------------------------------------------------------------------

[Levine, Daniel J.]

Regarding this statement:

That (1005) error may be caused by our unimplemented REJECT and
ASYNC_EVENT.

Perhaps iSCSI should spit out a message saying these are unsupported so
I can help you determine if this is the problem. Could a patch be
provided that will do this? I assume there isn't code in there already
to do this or we'd see it in our debug output/syslog output.

I'd love to see the output in syslog since the result, if indeed this is
what's going on, appears quite serious. :-(

Daniel J. Levine
A3C4 Section Supervisor
Air Defense Systems Department
Johns Hopkins University Applied Physics Laboratory
Phone: (443) 778-3952 (240) 228-3952

-----Original Message-----
From: open-...@googlegroups.com [mailto:open-...@googlegroups.com]
On Behalf Of Wang Zhenyu
Sent: Thursday, October 27, 2005 11:44 PM
To: open-...@googlegroups.com
Subject: Re: DataDigest corruption with Wasabi target

[Wang Zhenyu]

On 2005.10.28 08:27:41 +0000, Levine, Daniel J. wrote:
>
> Regarding this statement:
>
> That (1005) error may be caused by our unimplemented REJECT and
> ASYNC_EVENT.
>
> Perhaps iSCSI should spit out a message saying these are unsupported so
> I can help you determine if this is the problem. Could a patch be
> provided that will do this? I assume there isn't code in there already
> to do this or we'd see it in our debug output/syslog output.
>

ok, this's a patch I just sent to Albert to debug only.
We'll handle all that in future.

zhen

---

--- kernel/iscsi_tcp.c.orig 2005-10-09 23:22:45.000000000 +0800

+++ kernel/iscsi_tcp.c 2005-10-28 17:24:57.000000000 +0800
@@ -536,6 +536,22 @@ iscsi_r2t_rsp(struct iscsi_conn *conn, s
return 0;
}

+static void
+iscsi_reject_rsp(struct iscsi_conn *conn)
+{
+ /* FIXME: implement! */
+ printk(KERN_ERR "iscsi: reject PDU received!\n");
+ iscsi_conn_failure(conn, ISCSI_ERR_CONN_FAILED);
+}
+
+static void
+iscsi_async_event_rsp(struct iscsi_conn *conn)
+{
+ /* FIXME: implement! */
+ printk(KERN_ERR "iscsi: async event PDU received!\n");
+ iscsi_conn_failure(conn, ISCSI_ERR_CONN_FAILED);
+}
+
static int
iscsi_hdr_recv(struct iscsi_conn *conn)
{
@@ -772,10 +788,10 @@ iscsi_hdr_recv(struct iscsi_conn *conn)
rc = ISCSI_ERR_PROTO;
break;
case ISCSI_OP_REJECT:
- /* we need sth like iscsi_reject_rsp()*/
+ iscsi_reject_rsp(conn);
+ break;
case ISCSI_OP_ASYNC_EVENT:
- /* we need sth like iscsi_async_event_rsp() */
- rc = ISCSI_ERR_BAD_OPCODE;
+ iscsi_async_event_rsp(conn);
break;
default:
rc = ISCSI_ERR_BAD_OPCODE;

[Albert Pauw]

Yes,

consider DataDigest as a thing on the TODO list.

But we will get there, someday ;-)

Albert