Marco
2014-05-12 18:42:42 UTC
Hi,
I use VirtualBox to access a few iSCSI targets. Everything is
working fine and the performance is acceptable. But the log file on
the iSCSI server is filled with errors. The errors are reproducible
using FreeBSDs istgt target and Debians iscsi_trgt which makes me
assume the issue is related to VirtualBox rather than the target
software.
Here are some log file excerpts using a vanilla FreeNAS installation
(istgt) and an OpenMediaVault installation (Linux's iscsi_trgt):
Linux
-----
Apr 25 17:53:32 openmediavault kernel: [ 1338.505323] iscsi_trgt: scsi_cmnd_start(1022) 1d0e 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.506837] iscsi_trgt: check_segment_length(1800) data too long 1d0f 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.507586] iscsi_trgt: scsi_cmnd_start(1022) 1d0f 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.512276] iscsi_trgt: check_segment_length(1800) data too long 1d10 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.512979] iscsi_trgt: scsi_cmnd_start(1022) 1d10 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.513982] iscsi_trgt: check_segment_length(1800) data too long 1d11 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.515076] iscsi_trgt: scsi_cmnd_start(1022) 1d11 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.520322] iscsi_trgt: check_segment_length(1800) data too long 1d12 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.520860] iscsi_trgt: scsi_cmnd_start(1022) 1d12 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.521485] iscsi_trgt: check_segment_length(1800) data too long 1d13 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.522187] iscsi_trgt: scsi_cmnd_start(1022) 1d13 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.523245] iscsi_trgt: check_segment_length(1800) data too long 1d14 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.524781] iscsi_trgt: scsi_cmnd_start(1022) 1d14 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.528314] iscsi_trgt: check_segment_length(1800) data too long 1d15 40960 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.528971] iscsi_trgt: scsi_cmnd_start(1022) 1d15 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.529643] iscsi_trgt: check_segment_length(1800) data too long 1d16 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.530632] iscsi_trgt: scsi_cmnd_start(1022) 1d16 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.536930] iscsi_trgt: check_segment_length(1800) data too long 1d17 45056 8192
FreeBSD
-------
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695d5)
Apr 25 17:46:32 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695d7, TSIH=37, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695d7)
Apr 25 17:46:33 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695da, TSIH=38, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695da)
Apr 25 17:46:35 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695db, TSIH=39, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/37) QCmdSN(34) error
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695db)
Apr 25 17:46:36 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695e1, TSIH=40, CID=1, HeaderDigest=off, DataDigest=off
I used the following command to attach my iSCSI storage:
vboxmanage storageattach myvm \
--storagectl SATA \
--port 1 \
--medium iscsi \
--type hdd \
--server myserver \
--target iqn.mytarget:test
Version: 4.3.10 r39012
Why do I get those errors and how to get rid of them? I'm happy to
provide further information.
Regards
Marco
I use VirtualBox to access a few iSCSI targets. Everything is
working fine and the performance is acceptable. But the log file on
the iSCSI server is filled with errors. The errors are reproducible
using FreeBSDs istgt target and Debians iscsi_trgt which makes me
assume the issue is related to VirtualBox rather than the target
software.
Here are some log file excerpts using a vanilla FreeNAS installation
(istgt) and an OpenMediaVault installation (Linux's iscsi_trgt):
Linux
-----
Apr 25 17:53:32 openmediavault kernel: [ 1338.505323] iscsi_trgt: scsi_cmnd_start(1022) 1d0e 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.506837] iscsi_trgt: check_segment_length(1800) data too long 1d0f 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.507586] iscsi_trgt: scsi_cmnd_start(1022) 1d0f 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.512276] iscsi_trgt: check_segment_length(1800) data too long 1d10 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.512979] iscsi_trgt: scsi_cmnd_start(1022) 1d10 2a
Apr 25 17:53:32 openmediavault kernel: [ 1338.513982] iscsi_trgt: check_segment_length(1800) data too long 1d11 65536 8192
Apr 25 17:53:32 openmediavault kernel: [ 1338.515076] iscsi_trgt: scsi_cmnd_start(1022) 1d11 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.520322] iscsi_trgt: check_segment_length(1800) data too long 1d12 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.520860] iscsi_trgt: scsi_cmnd_start(1022) 1d12 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.521485] iscsi_trgt: check_segment_length(1800) data too long 1d13 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.522187] iscsi_trgt: scsi_cmnd_start(1022) 1d13 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.523245] iscsi_trgt: check_segment_length(1800) data too long 1d14 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.524781] iscsi_trgt: scsi_cmnd_start(1022) 1d14 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.528314] iscsi_trgt: check_segment_length(1800) data too long 1d15 40960 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.528971] iscsi_trgt: scsi_cmnd_start(1022) 1d15 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.529643] iscsi_trgt: check_segment_length(1800) data too long 1d16 65536 8192
Apr 25 17:53:33 openmediavault kernel: [ 1338.530632] iscsi_trgt: scsi_cmnd_start(1022) 1d16 2a
Apr 25 17:53:33 openmediavault kernel: [ 1338.536930] iscsi_trgt: check_segment_length(1800) data too long 1d17 45056 8192
FreeBSD
-------
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:31 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695d5)
Apr 25 17:46:32 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695d7, TSIH=37, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:32 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695d7)
Apr 25 17:46:33 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695da, TSIH=38, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/36) QCmdSN(33) error
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:34 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695da)
Apr 25 17:46:35 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695db, TSIH=39, CID=1, HeaderDigest=off, DataDigest=off
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:3640:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/37) QCmdSN(34) error
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:5053:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Apr 25 17:46:35 freenas istgt[1911]: istgt_iscsi.c:5728:worker: ***ERROR*** iscsi_execute() failed on iqn.2011-03.org.example.istgt:
foo,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1,i,0x8012345695db)
Apr 25 17:46:36 freenas istgt[1911]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:192.168.1.1 (192.168.1.1) on iqn.2011-03
org.example.istgt:foo LU1 (192.168.1.28:3260,1), ISID=8012345695e1, TSIH=40, CID=1, HeaderDigest=off, DataDigest=off
I used the following command to attach my iSCSI storage:
vboxmanage storageattach myvm \
--storagectl SATA \
--port 1 \
--medium iscsi \
--type hdd \
--server myserver \
--target iqn.mytarget:test
Version: 4.3.10 r39012
Why do I get those errors and how to get rid of them? I'm happy to
provide further information.
Regards
Marco