Can IBM POWER5-550 AIX 5.3l server connect to Starwind?

Software-based VM-centric and flash-friendly VM storage + free version

Moderators: anton (staff), art (staff), Max (staff), Anatoly (staff)

Locked
JOE-O
Posts: 2
Joined: Mon Feb 07, 2005 1:09 pm
Location: Philippines

Mon Feb 07, 2005 1:47 pm

Hi!

I've tried Starwind and am very pleased with its performance with Windows clients so far.

I'm evaluating Starwind for a client that has an IBM Power 5 e-server model 550 running 64 bit AIX ver. 5.3L which includes a native iSCSI driver for its GigE and 100Mbit ethernet NICs.

Even after updating the AIX OS and all its drivers to the latest available, we are still not able to connect to the Starwind iscsi server. Before we updated to the latest AIX OS level, we could not get even a hint of a connection. After the update, the AIX device list now shows an iscsi "hdisk1" with a "defined" label. For this to be accessible to the IBM server, its status label should be "available" and then a filesystem can be installed and mounted.

We tried all variations we could think of, but "defined" is the only status we got.

It looks like a connection is negotiated but just as quickly closed.

Following is the level 3 log. We would appreciate it if someone could take a look at it and suggest how we can make this work?

07:28:36:181 (6e4) Srv: StarWind iSCSI Target Version 2.4.3 (Build 0x20050116, Win32)
07:28:36:181 (6e4) Srv: *** FREE NON COMMERCIAL version ***
07:28:36:181 (6e4) Srv: Please contact Rocket Division Software at <info@rocketdivision.com> for more details.
07:28:36:181 (6e4) Srv: Maximum number of clients allowed: 2.
07:28:36:191 (6e4) Srv: Config file: 'C:\StarWind\starwind.conf'
07:28:36:231 (6e4) conf: 'LogLevel' = '3'
07:28:36:231 (6e4) conf: 'LogMask' = '0x8000ffff'
07:28:36:231 (6e4) conf: 'Port' = '3260'
07:28:36:231 (6e4) conf: 'Interface' = '0.0.0.0'
07:28:36:231 (6e4) conf: 'DefTargetName' = 'iqn.2003-06.com.rocketdivision.starwind:$(host).$(symid)'
07:28:36:231 (6e4) conf: 'Login' = 'test'
07:28:36:231 (6e4) conf: 'Password' = '##CY9rzUYh03PK3k6DJie09g=='
07:28:36:231 (6e4) conf: 'Echo' = 'no'
07:28:36:231 (6e4) conf: 'MinBufferSize' = '65536'
07:28:36:231 (6e4) conf: 'AlignmentMask' = '0x0000'
07:28:36:231 (6e4) conf: 'MaxPendingRequests' = '200'
07:28:36:231 (6e4) conf: Variable 'LogLevel' is set to '3'.
07:28:36:231 (6e4) conf: Variable 'LogMask' is set to '0x8000ffff'.
07:28:36:231 (6e4) conf: Variable 'Port' is set to '3260'.
07:28:36:231 (6e4) conf: Variable 'Interface' is set to '0.0.0.0'.
07:28:36:231 (6e4) conf: Variable 'DefTargetName' is set to 'iqn.2003-06.com.rocketdivision.starwind:$(host).$(symid)'.
07:28:36:231 (6e4) conf: Variable 'Login' is set to 'test'.
07:28:36:231 (6e4) conf: Variable 'Password' is set to '##CY9rzUYh03PK3k6DJie09g=='.
07:28:36:231 (6e4) conf: Variable 'Echo' is set to 'no'.
07:28:36:231 (6e4) conf: Variable 'MinBufferSize' is set to '65536'.
07:28:36:231 (6e4) conf: Variable 'AlignmentMask' is set to '0x0000'.
07:28:36:231 (6e4) conf: Variable 'MaxPendingRequests' is set to '200'.
RamDisk[6e4] *SscPort_Init: Logging level is set to 3.
RamDisk[6e4] *SscPort_Init:
VendorId = ' '
ProductId = ' '
Revision = '0001'
07:28:36:241 (6e4) func: >>> iScsiServer::addPlugin
07:28:36:241 (6e4) func: <<< iScsiServer::addPlugin
07:28:36:241 (6e4) conf: 'RamDisk.dll' loaded successfully.
ImageFile[6e4] *SscPort_Init: Logging level is set to 3.
ImageFile[6e4] *SscPort_Init:
VendorId = ' '
ProductId = ' '
Revision = '0001'
ImageDir = 'images\'
ImageMask = '*.img'
ExeDir = 'C:\StarWind\'
07:28:36:241 (6e4) func: >>> iScsiServer::addPlugin
07:28:36:241 (6e4) func: <<< iScsiServer::addPlugin
07:28:36:241 (6e4) conf: 'ImageFile.dll' loaded successfully.
VirtualDVD[6e4] *SscPort_Init: Logging level is set to 3.
VirtualDVD[6e4] *SscPort_Init:
VendorId = 'ROCKET '
ProductId = 'DVD-ROM F50 '
Revision = '1.00'
07:28:36:241 (6e4) func: >>> iScsiServer::addPlugin
07:28:36:241 (6e4) func: <<< iScsiServer::addPlugin
07:28:36:241 (6e4) conf: 'VirtualDvd.dll' loaded successfully.
07:28:36:241 (6e4) func: >>> iScsiServer::addDevice
07:28:36:241 (6e4) func: <<< iScsiServer::addDevice
07:28:36:241 (6e4) func: >>> iScsiSscDevice::open
ImageFile[6e4] SscPort_Create: Create 'ImageFile0'...
ImageFile[6e4] *SscPort_Create: Opening device 'ImageFile0', image file 'c:\500mb.img'.
ImageFile[6e4] ImageFile_Create: Disk structure allocated OK
ImageFile[6e4] *ImageFile_Create: 'c:\500mb.img': Disk geometry: Sect/Track= 16, Tracks/Cyl= 32, Ncyl= 2000, TotalSectors: 1024000
ImageFile[6e4]->ImageFile_BuildInquiry >>
ImageFile[6e4] *ImageFile_BuildInquiry: Use default VendorId
ImageFile[6e4] *ImageFile_BuildInquiry: Use default ProductId
ImageFile[6e4] *ImageFile_BuildInquiry:
VendorId = 'ROCKET '
ProductId = 'IMG DISK 500 MB '
Revision = '0001'
ImageFile[6e4]<-ImageFile_BuildInquiry << Return (0x0)
ImageFile[6e4] ImageFile_Create: Disk creation succeded.
07:28:36:241 (6e4) func: <<< iScsiSscDevice::open
07:28:36:241 (6e4) S: the device 'ImageFile0' is opened successfully.
07:28:36:241 (6e4) S: Assigned target name: 'iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0', SymId: 'Imagefile.ImageFile0'.
07:28:36:241 (6e4) S: parameter 'header', value '0'.
07:28:36:241 (6e4) S: parameter 'file', value 'c:\500mb.img'.
07:28:36:241 (6e4) S: parameter 'buffering', value 'no'.
07:28:36:241 (6e4) S: clustered 0.
07:28:36:241 (6e4) S: parameter 'asyncmode', value 'no'.
07:28:36:241 (6e4) S: iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0: 1 session(s) allowed.
07:28:36:241 (6e4) conf: Target [0x9a928] has been created. Device 'ImageFile0' is accesible as target 'iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0'.
07:28:36:241 (6e4) func: >>> iScsiServer::refreshDeviceList
07:28:36:241 (6e4) Srv: Refreshing device list...
07:28:41:438 (6e4) func: >>> iScsiSptiDevice::open
07:28:41:528 (6e4) func: >>> iScsiSptiDevice::openDevice
07:28:41:528 (6e4) SPTI: '\\.\D:': Cannot open the device: The process cannot access the file because it is being used by another process. (code: 32).
07:28:41:528 (6e4) func: <<< iScsiSptiDevice::openDevice
07:28:41:528 (6e4) func: >>> iScsiSptiDevice::closeDevice
07:28:41:528 (6e4) func: <<< iScsiSptiDevice::closeDevice
07:28:41:528 (6e4) func: <<< iScsiSptiDevice::open
07:28:41:528 (6e4) Srv: Failed to open the device '\\.\D:'.
07:28:41:699 (6e4) func: >>> iScsiSptiDevice::open
07:28:41:699 (6e4) func: >>> iScsiSptiDevice::openDevice
07:28:41:709 (6e4) func: >>> iScsiSptiDevice::probe
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::probe
07:28:41:719 (6e4) SPTI: '\\.\Z:': DeviceType 5, DeviceTypeModifier 0, RemovableMedia true, VendorId '', ProductId 'TEAC CD-224E-BA', ProductRevision '7.7C', BusType 2.
07:28:41:719 (6e4) SPTI: '\\.\Z:': MaximumTransferLength 131072, MaximumPhysicalPages 0xffffffff, AlignmentMask 0x1, BusType 3
07:28:41:719 (6e4) SPTI: '\\.\Z:': ' TEAC CD-224E-BA 7.7C': adapter 1, bus 0, target id 0, LUN 0; maxTransferLength 131072
07:28:41:719 (6e4) func: >>> iScsiSptiDevice::getBurnerFlags
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::getBurnerFlags
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::openDevice
07:28:41:719 (6e4) func: >>> iScsiSptiDevice::closeDevice
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::closeDevice
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::open
07:28:41:719 (6e4) func: >>> iScsiSptiDevice::close
07:28:41:719 (6e4) func: <<< iScsiSptiDevice::close
07:28:41:719 (6e4) Srv: A new SPTI device '\\.\Z:' found.
07:28:41:719 (6e4) func: >>> iScsiServer::addDevice
07:28:41:719 (6e4) func: <<< iScsiServer::addDevice
07:28:41:729 (6e4) func: >>> iScsiSptiDevice::open
07:28:41:729 (6e4) func: >>> iScsiSptiDevice::openDevice
07:28:41:919 (6e4) func: >>> iScsiSptiDevice::probe
07:28:41:939 (6e4) func: <<< iScsiSptiDevice::probe
07:28:41:969 (6e4) SPTI: '\\.\Cdrom0': DeviceType 5, DeviceTypeModifier 0, RemovableMedia true, VendorId '', ProductId 'TEAC CD-224E-BA', ProductRevision '7.7C', BusType 2.
07:28:41:969 (6e4) SPTI: '\\.\Cdrom0': MaximumTransferLength 131072, MaximumPhysicalPages 0xffffffff, AlignmentMask 0x1, BusType 3
07:28:41:969 (6e4) SPTI: '\\.\Cdrom0': ' TEAC CD-224E-BA 7.7C': adapter 1, bus 0, target id 0, LUN 0; maxTransferLength 131072
07:28:41:969 (6e4) func: >>> iScsiSptiDevice::getBurnerFlags
07:28:42:099 (6e4) func: <<< iScsiSptiDevice::getBurnerFlags
07:28:42:099 (6e4) func: <<< iScsiSptiDevice::openDevice
07:28:42:099 (6e4) func: >>> iScsiSptiDevice::closeDevice
07:28:42:099 (6e4) func: <<< iScsiSptiDevice::closeDevice
07:28:42:099 (6e4) func: <<< iScsiSptiDevice::open
07:28:42:099 (6e4) Srv: SCSI device '\\.\Cdrom0' is an alias of '\\.\Z:'
07:28:42:099 (6e4) Srv: The device '\\.\Cdrom0' is not allowed by the server.
07:28:42:099 (6e4) func: >>> iScsiSptiDevice::close
07:28:42:099 (6e4) func: <<< iScsiSptiDevice::close
07:28:42:099 (6e4) SPTI: '\\.\PhysicalDrive0': Hard drive name: '\\.\PhysicalDrive0'
07:28:42:099 (6e4) func: >>> iScsiSptiDevice::open
07:28:42:099 (6e4) func: >>> iScsiSptiDevice::openDevice
07:28:42:109 (6e4) func: >>> iScsiSptiDevice::probe
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::probe
07:28:42:109 (6e4) SPTI: '\\.\PhysicalDrive0': DeviceType 0, DeviceTypeModifier 0, RemovableMedia false, VendorId '', ProductId 'TOSHIBA MK2016GAP', ProductRevision 'U0.33 A', BusType 3.
07:28:42:109 (6e4) SPTI: '\\.\PhysicalDrive0': MaximumTransferLength 131072, MaximumPhysicalPages 0xffffffff, AlignmentMask 0x1, BusType 3
07:28:42:109 (6e4) SPTI: '\\.\PhysicalDrive0': ' TOSHIBA MK2016GAP U0.33 A': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 131072
07:28:42:109 (6e4) func: >>> iScsiSptiDevice::getBurnerFlags
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::getBurnerFlags
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::openDevice
07:28:42:109 (6e4) func: >>> iScsiSptiDevice::closeDevice
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::closeDevice
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::open
07:28:42:109 (6e4) func: >>> iScsiSptiDevice::close
07:28:42:109 (6e4) func: <<< iScsiSptiDevice::close
07:28:42:109 (6e4) Srv: A new SPTI device '\\.\PhysicalDrive0' found.
07:28:42:109 (6e4) func: >>> iScsiServer::addDevice
07:28:42:109 (6e4) func: <<< iScsiServer::addDevice
ImageFile[6e4] ProcessVolumeLetters: Found volume '\\?\Volume{db940df0-36b8-11d9-8038-806d6172696f}\', mount point 'C:\'.
ImageFile[6e4] ProcessVolumeLetters: Found volume '\\?\Volume{db940df1-36b8-11d9-8038-806d6172696f}\', mount point 'D:\'.
ImageFile[6e4] ProcessVolumeLetters: Found volume '\\?\Volume{df4911b1-18f6-11d6-a600-806d6172696f}\', mount point 'Z:\'.
ImageFile[6e4] ProcessVolumes: Found volume '\\?\Volume{df4911b2-18f6-11d6-a600-806d6172696f}\', no mount point.
ImageFile[6e4] List_RefreshVolumes: '\\?\Volume{df4911b2-18f6-11d6-a600-806d6172696f}' is not a hard drive volume (err: 1)
ImageFile[6e4] List_RefreshVolumes: '\\.\Z:' is not a hard drive volume (err: 1)
ImageFile[6e4] *List_RefreshVolumes: Adding device 'ImageFile1' for volume '\\.\D:'.
ImageFile[6e4] *List_RefreshVolumes: Adding device 'ImageFile2' for volume '\\.\C:'.
07:28:42:860 (6e4) func: >>> iScsiSscDevice::open
ImageFile[6e4] SscPort_Create: Create 'ImageFile2'...
ImageFile[6e4] *SscPort_Create: Removing old item: 'ImageFile2'...
ImageFile[6e4] *SscPort_Create: Opening device 'ImageFile2', image file '\\.\C:'.
ImageFile[6e4] *ERROR* ImageFile_Create: '\\.\C:': cannot open the image file (32).
07:28:48:689 (6e4) SCSI: Failed to create 'ImageFile2' device.
07:28:48:689 (6e4) func: <<< iScsiSscDevice::open
07:28:48:689 (6e4) Plugin: Test for device 'ImageFile2' failed.
07:28:48:689 (6e4) func: >>> iScsiSscDevice::open
ImageFile[6e4] SscPort_Create: Create 'ImageFile1'...
ImageFile[6e4] *SscPort_Create: Removing old item: 'ImageFile1'...
ImageFile[6e4] *SscPort_Create: Opening device 'ImageFile1', image file '\\.\D:'.
ImageFile[6e4] ImageFile_Create: Disk structure allocated OK
ImageFile[6e4] *ImageFile_Create: '\\.\D:': Disk geometry: Sect/Track= 16, Tracks/Cyl= 32, Ncyl= 32004, TotalSectors: 16386048
ImageFile[6e4]->ImageFile_BuildInquiry >>
ImageFile[6e4] *ImageFile_BuildInquiry: Use default VendorId
ImageFile[6e4] *ImageFile_BuildInquiry: Use default ProductId
ImageFile[6e4] *ImageFile_BuildInquiry:
VendorId = 'ROCKET '
ProductId = 'IMG DISK 8001 MB'
Revision = '0001'
ImageFile[6e4]<-ImageFile_BuildInquiry << Return (0x0)
ImageFile[6e4] ImageFile_Create: Disk creation succeded.
07:28:48:789 (6e4) func: <<< iScsiSscDevice::open
07:28:48:789 (6e4) func: >>> iScsiSscDevice::close
ImageFile[6e4] ImageFile_Close: Closing the disk...
07:28:48:789 (6e4) func: <<< iScsiSscDevice::close
07:28:48:789 (6e4) func: >>> iScsiServer::addDevice
07:28:48:789 (6e4) func: <<< iScsiServer::addDevice
07:28:48:789 (6e4) func: <<< iScsiServer::refreshDeviceList
07:28:48:789 (6e4) func: >>> iScsiServer::listenConnections
07:28:48:789 (590) func: >>> TelnetListener::listenConnections
07:28:49:199 (6e4) Srv: (FREE) Binding to 0.0.0.0:3260 ...
07:28:49:219 (6e4) Srv: Waiting for a connection at port 0.0.0.0:3260 ...
07:28:49:219 (590) conf: Waiting for a control connection at port 3261 ...
07:29:12:613 (590) conf: Accepted the control connection from 127.0.0.1:1028.
07:29:12:643 (6e0) conf: send: '[2JStarWind iSCSI Target Version 2.4.3 (Build 0x20050116, Win32)
Copyright (c) Rocket Division Software 2003-2005. All rights reserved.

Type a command or 'help' for more info.

'
07:29:12:673 (6e0) func: >>> ControlConnection::doLogon
07:29:12:673 (6e0) conf: send: '200 Completed.


'
07:29:12:693 (6e0) func: <<< ControlConnection::doLogon
07:29:12:713 (6e0) func: >>> ControlConnection::doList
07:29:12:713 (6e0) conf: Loaded 'list':
07:29:12:713 (6e0) conf: -what:"devices"
07:29:12:713 (6e0) func: >>> iScsiServer::list
07:29:12:713 (6e0) Srv: -rescan:'0'
07:29:12:713 (6e0) Srv: -what:'devices'
07:29:12:713 (6e0) func: <<< iScsiServer::list
07:29:12:713 (6e0) conf: send: '200 Completed.
DeviceName="ImageFile0"
DeviceId="0x9a928"
DeviceType="Image file"
TargetName="iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0"
header="0"
file="c:\500mb.img"
buffering="no"
clustered="no"
asyncmode="no"
DeviceName="\\.\Z:"
DeviceId="0x98f48"
DeviceType="SPTI:CD/DVD"
sessions="1"
ScsiInquiry=" TEAC CD-224E-BA 7.7C"
ScsiAdapter="1"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="\\.\PhysicalDrive0"
DeviceId="0x9b090"
DeviceType="SPTI:Disk"
sessions="1"
ScsiInquiry=" TOSHIBA MK2016GAP U0.33 A"
ScsiAdapter="0"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="ImageFile1"
DeviceId="0x9afc8"
DeviceType="Image file"

[0x9a928]: 'ImageFile0' accesible as target 'iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0'
[0x98f48]: '\\.\Z:'
[0x9b090]: '\\.\PhysicalDrive0'
[0x9afc8]: 'ImageFile1'

'
07:29:12:713 (6e0) func: <<< ControlConnection::doList
07:29:12:713 (6e0) func: >>> ControlConnection::doStatistics
07:29:12:713 (6e0) conf: send: '104 Command rejected by the server.
Uptime="0 day(s) 0:00:36"

Wrong device id [0x0].

'
07:29:12:713 (6e0) func: <<< ControlConnection::doStatistics
07:29:19:263 (6e0) func: >>> ControlConnection::doRemove
07:29:19:263 (6e0) func: >>> iScsiServer::remove
07:29:19:263 (6e0) Srv: Removing target 'iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0'...
07:29:19:263 (6e0) func: >>> iScsiSscDevice::close
ImageFile[6e0] ImageFile_Close: Closing the disk...
07:29:19:263 (6e0) func: <<< iScsiSscDevice::close
07:29:19:263 (6e0) S: the device 'ImageFile0' is closed.
07:29:19:263 (6e0) func: <<< iScsiServer::remove
07:29:19:283 (6e0) conf: send: '200 Completed.

The target 'iqn.2003-06.com.rocketdivision.starwind:gabc-t1800.imagefile.imagefile0' has been removed.

'
07:29:19:303 (6e0) func: <<< ControlConnection::doRemove
07:29:19:343 (6e0) func: >>> ControlConnection::doList
07:29:19:343 (6e0) conf: Loaded 'list':
07:29:19:343 (6e0) conf: -what:"devices"
07:29:19:343 (6e0) func: >>> iScsiServer::list
07:29:19:343 (6e0) Srv: -rescan:'0'
07:29:19:343 (6e0) Srv: -what:'devices'
07:29:19:343 (6e0) func: <<< iScsiServer::list
07:29:19:343 (6e0) conf: send: '200 Completed.
DeviceName="ImageFile0"
DeviceId="0x9a928"
DeviceType="Image file"
DeviceName="\\.\Z:"
DeviceId="0x98f48"
DeviceType="SPTI:CD/DVD"
sessions="1"
ScsiInquiry=" TEAC CD-224E-BA 7.7C"
ScsiAdapter="1"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="\\.\PhysicalDrive0"
DeviceId="0x9b090"
DeviceType="SPTI:Disk"
sessions="1"
ScsiInquiry=" TOSHIBA MK2016GAP U0.33 A"
ScsiAdapter="0"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="ImageFile1"
DeviceId="0x9afc8"
DeviceType="Image file"

[0x9a928]: 'ImageFile0'
[0x98f48]: '\\.\Z:'
[0x9b090]: '\\.\PhysicalDrive0'
[0x9afc8]: 'ImageFile1'

'
07:29:19:343 (6e0) func: <<< ControlConnection::doList
07:29:27:324 (6e0) func: >>> ControlConnection::doList
07:29:27:324 (6e0) conf: Loaded 'list':
07:29:27:324 (6e0) conf: -what:"devices"
07:29:27:324 (6e0) conf: -rescan:"1"
07:29:27:324 (6e0) func: >>> iScsiServer::list
07:29:27:324 (6e0) Srv: -rescan:'1'
07:29:27:324 (6e0) Srv: -what:'devices'
07:29:27:324 (6e0) func: >>> iScsiServer::refreshDeviceList
07:29:27:324 (6e0) Srv: Refreshing device list...
ImageFile[6e0] ProcessVolumeLetters: Found volume '\\?\Volume{db940df0-36b8-11d9-8038-806d6172696f}\', mount point 'C:\'.
ImageFile[6e0] ProcessVolumeLetters: Found volume '\\?\Volume{db940df1-36b8-11d9-8038-806d6172696f}\', mount point 'D:\'.
ImageFile[6e0] ProcessVolumeLetters: Found volume '\\?\Volume{df4911b1-18f6-11d6-a600-806d6172696f}\', mount point 'Z:\'.
ImageFile[6e0] ProcessVolumes: Found volume '\\?\Volume{df4911b2-18f6-11d6-a600-806d6172696f}\', no mount point.
ImageFile[6e0] List_RefreshVolumes: '\\?\Volume{df4911b2-18f6-11d6-a600-806d6172696f}' is not a hard drive volume (err: 1)
ImageFile[6e0] List_RefreshVolumes: '\\.\Z:' is not a hard drive volume (err: 1)
07:29:27:454 (6e0) func: >>> iScsiSscDevice::open
ImageFile[6e0] SscPort_Create: Create 'ImageFile2'...
ImageFile[6e0] *SscPort_Create: Removing old item: 'ImageFile2'...
ImageFile[6e0] *SscPort_Create: Opening device 'ImageFile2', image file '\\.\C:'.
ImageFile[6e0] *ERROR* ImageFile_Create: '\\.\C:': cannot open the image file (32).
07:29:32:431 (6e0) SCSI: Failed to create 'ImageFile2' device.
07:29:32:431 (6e0) func: <<< iScsiSscDevice::open
07:29:32:431 (6e0) Plugin: Test for device 'ImageFile2' failed.
07:29:32:431 (6e0) func: <<< iScsiServer::refreshDeviceList
07:29:32:431 (6e0) func: <<< iScsiServer::list
07:29:32:431 (6e0) conf: send: '200 Completed.
DeviceName="ImageFile0"
DeviceId="0x9a928"
DeviceType="Image file"
DeviceName="\\.\Z:"
DeviceId="0x98f48"
DeviceType="SPTI:CD/DVD"
sessions="1"
ScsiInquiry=" TEAC CD-224E-BA 7.7C"
ScsiAdapter="1"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="\\.\PhysicalDrive0"
DeviceId="0x9b090"
DeviceType="SPTI:Disk"
sessions="1"
ScsiInquiry=" TOSHIBA MK2016GAP U0.33 A"
ScsiAdapter="0"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="ImageFile1"
DeviceId="0x9afc8"
DeviceType="Image file"

[0x9a928]: 'ImageFile0'
[0x98f48]: '\\.\Z:'
[0x9b090]: '\\.\PhysicalDrive0'
[0x9afc8]: 'ImageFile1'

'
07:29:32:431 (6e0) func: <<< ControlConnection::doList
07:30:53:588 (6e0) func: >>> ControlConnection::doAdd
07:30:53:588 (6e0) conf: Loaded 'add':
07:30:53:588 (6e0) conf: "ImageFile0"
07:30:53:588 (6e0) conf: "iqn.com.test500mb"
07:30:53:588 (6e0) conf: -file:"c:\500mb.img"
07:30:53:588 (6e0) conf: -header:"0"
07:30:53:588 (6e0) func: >>> iScsiSscDevice::open
ImageFile[6e0] SscPort_Create: Create 'ImageFile0'...
ImageFile[6e0] *SscPort_Create: Removing old item: 'ImageFile0'...
ImageFile[6e0] *SscPort_Create: Opening device 'ImageFile0', image file 'c:\500mb.img'.
ImageFile[6e0] ImageFile_Create: Disk structure allocated OK
ImageFile[6e0] *ImageFile_Create: 'c:\500mb.img': Disk geometry: Sect/Track= 16, Tracks/Cyl= 32, Ncyl= 2000, TotalSectors: 1024000
ImageFile[6e0]->ImageFile_BuildInquiry >>
ImageFile[6e0] *ImageFile_BuildInquiry: Use default VendorId
ImageFile[6e0] *ImageFile_BuildInquiry: Use default ProductId
ImageFile[6e0] *ImageFile_BuildInquiry:
VendorId = 'ROCKET '
ProductId = 'IMG DISK 500 MB '
Revision = '0001'
ImageFile[6e0]<-ImageFile_BuildInquiry << Return (0x0)
ImageFile[6e0] ImageFile_Create: Disk creation succeded.
07:30:53:668 (6e0) func: <<< iScsiSscDevice::open
07:30:53:668 (6e0) S: the device 'ImageFile0' is opened successfully.
07:30:53:668 (6e0) S: Assigned target name: 'iqn.com.test500mb', SymId: 'Imagefile.ImageFile0'.
07:30:53:668 (6e0) S: parameter 'header', value '0'.
07:30:53:668 (6e0) S: parameter 'file', value 'c:\500mb.img'.
07:30:53:668 (6e0) S: parameter 'buffering', value 'no'.
07:30:53:668 (6e0) S: clustered 0.
07:30:53:668 (6e0) S: parameter 'asyncmode', value 'no'.
07:30:53:668 (6e0) S: iqn.com.test500mb: 1 session(s) allowed.
07:30:53:668 (6e0) conf: Target [0x9a928] has been created. Device 'ImageFile0' is accesible as target 'iqn.com.test500mb'.
07:30:53:668 (6e0) conf: send: '200 Completed.
DeviceName="ImageFile0"
DeviceId="0x9a928"
DeviceType="Image file"
TargetName="iqn.com.test500mb"
header="0"
file="c:\500mb.img"
buffering="no"
clustered="no"
asyncmode="no"

[0x9a928]: 'ImageFile0' accesible as target 'iqn.com.test500mb'

'
07:30:53:738 (6e0) func: <<< ControlConnection::doAdd
07:30:53:738 (6e0) func: >>> ControlConnection::doStatistics
07:30:53:738 (6e0) conf: send: '104 Command rejected by the server.
Uptime="0 day(s) 0:02:17"

Wrong device id [0x0].

'
07:30:53:738 (6e0) func: <<< ControlConnection::doStatistics
07:30:53:748 (6e0) func: >>> ControlConnection::doList
07:30:53:748 (6e0) conf: Loaded 'list':
07:30:53:748 (6e0) conf: -what:"devices"
07:30:53:748 (6e0) func: >>> iScsiServer::list
07:30:53:748 (6e0) Srv: -rescan:'0'
07:30:53:748 (6e0) Srv: -what:'devices'
07:30:53:748 (6e0) func: <<< iScsiServer::list
07:30:53:748 (6e0) conf: send: '200 Completed.
DeviceName="ImageFile0"
DeviceId="0x9a928"
DeviceType="Image file"
TargetName="iqn.com.test500mb"
header="0"
file="c:\500mb.img"
buffering="no"
clustered="no"
asyncmode="no"
DeviceName="\\.\Z:"
DeviceId="0x98f48"
DeviceType="SPTI:CD/DVD"
sessions="1"
ScsiInquiry=" TEAC CD-224E-BA 7.7C"
ScsiAdapter="1"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="\\.\PhysicalDrive0"
DeviceId="0x9b090"
DeviceType="SPTI:Disk"
sessions="1"
ScsiInquiry=" TOSHIBA MK2016GAP U0.33 A"
ScsiAdapter="0"
ScsiBus="0"
ScsiTarget="0"
ScsiLun="0"
DeviceName="ImageFile1"
DeviceId="0x9afc8"
DeviceType="Image file"

[0x9a928]: 'ImageFile0' accesible as target 'iqn.com.test500mb'
[0x98f48]: '\\.\Z:'
[0x9b090]: '\\.\PhysicalDrive0'
[0x9afc8]: 'ImageFile1'

'
07:30:53:748 (6e0) func: <<< ControlConnection::doList
07:30:53:748 (6e0) func: >>> ControlConnection::doStatistics
07:30:53:748 (6e0) conf: send: '104 Command rejected by the server.
Uptime="0 day(s) 0:02:17"

Wrong device id [0x0].

'
07:30:53:748 (6e0) func: <<< ControlConnection::doStatistics
07:31:33:976 (6e4) Srv: Accepted connection from 150.200.3.14:33125. id assigned - 4370
07:31:33:976 (6e4) func: >>> iScsiServer::addConnection
07:31:33:976 (6e4) func: <<< iScsiServer::addConnection
07:31:33:976 (6e4) func: >>> iScsiConnection::start
07:31:33:976 (6e4) func: >>> iScsiServer::removeConnection
07:31:33:976 (6e4) func: <<< iScsiServer::removeConnection
07:31:33:976 (6e4) func: >>> iScsiSession::addConnection
07:31:33:976 (6e4) func: <<< iScsiSession::addConnection
07:31:33:976 (6e4) func: >>> iScsiServer::addSession
07:31:33:976 (6e4) func: <<< iScsiServer::addSession
07:31:33:976 (6e4) func: >>> iScsiConnection::doTransition
07:31:33:976 (6e4) C[0x1112], FREE: Event - CONNECTED.
07:31:33:976 (6e4) C[0x1112], XPT_UP: T3.
07:31:33:976 (6e4) func: <<< iScsiConnection::doTransition
07:31:33:976 (6e4) func: >>> iScsiSession::start
07:31:33:976 (6e4) func: <<< iScsiSession::start
07:31:33:976 (6e4) func: <<< iScsiConnection::start
07:31:33:976 (5c0) C[0x1112], XPT_UP: Recv thread priority: 1
07:31:33:976 (5c0) func: >>> iScsiConnection::receive
07:31:33:976 (5c0) func: >>> iScsiConnection::recvData
07:31:33:986 (600) C[0x1112], XPT_UP: Send thread priority: 0
07:31:33:986 (698) S[0x2222]: Session exec thread priority: 2
07:31:34:978 (5c0) func: <<< iScsiConnection::recvData
07:31:34:978 (5c0) func: >>> iScsiConnection::handleFirstLogin
07:31:34:978 (5c0) C[0x1112], XPT_UP: Login request: ISID 0x800000000001, TSIH 0x0000.
07:31:34:978 (5c0) func: >>> iScsiConnection::handlePdu
07:31:34:978 (5c0) C[0x1112], XPT_UP: >> PDU: Opcode 3, I: ITT 0x0, CmdSn 201326091, ExpStatSN 0; T: ExpCmdSN 201326091, MaxCmdSN 201326290.
07:31:34:978 (5c0) func: >>> iScsiTaskList::allocateTask
07:31:34:978 (5c0) func: <<< iScsiTaskList::allocateTask
07:31:34:978 (5c0) C[0x1112], XPT_UP: New task has been created (0): ITT 0x0.
07:31:34:978 (5c0) func: >>> iScsiTask::handlePdu
07:31:34:978 (5c0) func: >>> iScsiTask::handleFirstLoginReq
07:31:34:978 (5c0) func: >>> iScsiParams::allocateDefault
07:31:34:978 (5c0) func: <<< iScsiParams::allocateDefault
07:31:34:978 (5c0) func: >>> iScsiConnection::doTransition
07:31:34:978 (5c0) C[0x1112], XPT_UP: Event - LOGIN.
07:31:34:978 (5c0) C[0x1112], IN_LOGIN: T4.
07:31:34:978 (5c0) func: <<< iScsiConnection::doTransition
07:31:34:978 (5c0) func: >>> iScsiTask::recvLoginText
07:31:34:978 (5c0) func: >>> iScsiConnection::recvData
07:31:34:978 (5c0) func: <<< iScsiConnection::recvData
07:31:34:978 (5c0) func: <<< iScsiTask::recvLoginText
07:31:34:978 (5c0) func: >>> iScsiParams::updateFromString
07:31:34:978 (5c0) Params: <<< String param 'InitiatorName': received 'iqn.localhost.hostid.7f000001', accepted 'iqn.localhost.hostid.7f000001'
07:31:34:978 (5c0) Params: <<< String param 'TargetName': received 'iqn.com.test500mb', accepted 'iqn.com.test500mb'
07:31:34:978 (5c0) Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
07:31:34:978 (5c0) Params: <<< Numeric param 'MaxConnections': received 1, accepted 1
07:31:34:978 (5c0) Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 524288, accepted 524288
07:31:34:978 (5c0) Params: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
07:31:34:978 (5c0) Params: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
07:31:34:978 (5c0) Params: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
07:31:34:978 (5c0) Params: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
07:31:34:978 (5c0) Params: Update OFMarkInt according to the value of OFMarker.
07:31:34:978 (5c0) Params: Update IFMarkInt according to the value of IFMarker.
07:31:34:978 (5c0) func: <<< iScsiParams::updateFromString
07:31:34:978 (5c0) func: >>> iScsiTask::startLoginPhase
07:31:34:978 (5c0) S: iqn.com.test500mb: 1 session(s) are opened, 0 more allowed.
07:31:34:978 (5c0) func: <<< iScsiTask::startLoginPhase
07:31:34:978 (5c0) func: >>> iScsiTask::handleAuth
07:31:34:978 (5c0) T[0x0]: Anonymous connection allowed.
07:31:34:978 (5c0) func: <<< iScsiTask::handleAuth
07:31:34:978 (5c0) func: >>> iScsiParams::createKeys
07:31:34:978 (5c0) Params: >>> ErrorRecoveryLevel=0.
07:31:34:978 (5c0) Params: >>> MaxConnections=1.
07:31:34:978 (5c0) Params: >>> InitialR2T=No.
07:31:34:978 (5c0) Params: >>> ImmediateData=Yes.
07:31:34:978 (5c0) Params: >>> MaxRecvDataSegmentLength=65536.
07:31:34:978 (5c0) Params: >>> FirstBurstLength=65536.
07:31:34:978 (5c0) Params: >>> DefaultTime2Wait=2.
07:31:34:978 (5c0) Params: >>> MaxOutstandingR2T=1.
07:31:34:978 (5c0) Params: >>> DataPDUInOrder=Yes.
07:31:34:978 (5c0) Params: >>> DataSequenceInOrder=Yes.
07:31:34:978 (5c0) Params: >>> TargetPortalGroupTag=1.
07:31:34:978 (5c0) func: <<< iScsiParams::createKeys
07:31:34:978 (5c0) T[0x0]: State transition postponed: authentication required or some key requires negotiation.
07:31:34:978 (5c0) func: >>> iScsiTask::setState
07:31:34:978 (5c0) T[0x0]: setState 0x30.
07:31:34:978 (5c0) func: <<< iScsiTask::setState
07:31:34:978 (5c0) func: <<< iScsiTask::handleFirstLoginReq
07:31:34:978 (5c0) func: <<< iScsiTask::handlePdu
07:31:34:978 (5c0) func: <<< iScsiConnection::handlePdu
07:31:34:988 (698) func: >>> iScsiSession::execute
07:31:34:988 (698) S[0x2222]: Executing task: CmdSN 201326091, ITT 0x0.
07:31:34:988 (698) func: >>> iScsiTask::execute
07:31:34:988 (698) func: >>> iScsiTask::execLoginReq
07:31:34:988 (698) func: >>> iScsiTask::setState
07:31:34:988 (698) T[0x0]: setState 0x700.
07:31:34:988 (698) func: <<< iScsiTask::setState
07:31:34:988 (698) func: <<< iScsiTask::execLoginReq
07:31:34:988 (698) func: <<< iScsiTask::execute
07:31:34:988 (698) func: <<< iScsiSession::execute
07:31:34:978 (5c0) func: <<< iScsiConnection::handleFirstLogin
07:31:34:988 (5c0) func: <<< iScsiConnection::receive
07:31:34:988 (5c0) func: >>> iScsiConnection::receive
07:31:34:988 (5c0) func: >>> iScsiConnection::recvData
07:31:34:988 (600) func: >>> iScsiConnection::send
07:31:34:988 (600) func: >>> iScsiTask::sendBufsCount
07:31:34:988 (600) func: <<< iScsiTask::sendBufsCount
07:31:34:988 (600) func: >>> iScsiTask::sendFillBufs
07:31:34:988 (600) T[0x0]: << PDU: OpCode 35, StatSN 0, ExpCmdSN 201326091, MaxCmdSN 201326290.
07:31:34:988 (600) func: <<< iScsiTask::sendFillBufs
07:31:34:988 (600) func: >>> iScsiTask::sendComplete
07:31:34:988 (600) func: >>> iScsiTask::setState
07:31:34:988 (600) T[0x0]: setState 0x2.
07:31:34:988 (600) func: <<< iScsiTask::setState
07:31:34:988 (600) func: <<< iScsiTask::sendComplete
07:31:34:988 (600) func: >>> iScsiTaskList::freeCompleted
07:31:34:988 (600) func: <<< iScsiTaskList::freeCompleted
07:31:34:988 (600) func: <<< iScsiConnection::send
07:31:34:988 (5c0) func: <<< iScsiConnection::recvData
07:31:34:988 (5c0) func: <<< iScsiConnection::receive
07:31:34:988 (5c0) C[0x1112], IN_LOGIN: *ERROR* 'recv' thread: recv failed 274a.
07:31:34:988 (5c0) func: >>> iScsiConnection::initiateShutdown
07:31:34:988 (5c0) func: >>> iScsiConnection::pingTimeout
07:31:34:988 (5c0) S[0x2222]: Session state dump: ExpCmdSN 0xbfffe0b, MaxCmdSN 0xbfffed2
07:31:34:988 (5c0) C[0x1112], IN_LOGIN: StatSN 0x1
07:31:34:988 (5c0) T[0x0]: state 0x2, immediate 1, ITT 0x0, CmdSn 0xbfffe0b, TTT 0x2
07:31:34:988 (5c0) T[0x0]: read/write 11, read length 229, read done 0, write length 223, write done 0, DATA-IN PDUs 0
07:31:34:988 (5c0) T[0x0]: DataSN 0, R2TSN 0, status 0, status class 0, status detail 0, response 0, counter 1, authStage 4
07:31:34:988 (5c0) T[0x0]: CDB
0000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
07:31:34:988 (5c0) T[0x0]: Sense 0 bytes
0000 65 20 61 73 20 74 61 72 67 65 74 20 27 69 71 6e e as target 'iqn
0010 2e 63 .c
07:31:34:988 (5c0) T[0x0]: SSC
0000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0040 00 00 00 00 00 00 00 00 ........
07:31:34:988 (5c0) C[0x1112], IN_LOGIN: << NOP-in: StatSN 1, ExpCmdSN 201326091, MaxCmdSN 201326290.
07:31:34:988 (5c0) func: <<< iScsiConnection::pingTimeout
07:31:34:988 (5c0) func: <<< iScsiConnection::initiateShutdown
07:31:34:988 (5c0) func: >>> iScsiConnection::waitForShutdownComplete
07:31:34:988 (5c0) func: <<< iScsiConnection::waitForShutdownComplete
07:31:34:988 (600) C[0x1112], IN_LOGIN: 'send' thread: stop command received, exiting...
07:31:34:988 (600) func: >>> iScsiConnection::waitForShutdownComplete
07:31:34:988 (600) C[0x1112], IN_LOGIN: 'recv' thread: stopping...
07:31:34:988 (600) C[0x1112], IN_LOGIN: 'recv' thread: stopped successfully.
07:31:34:988 (698) func: >>> iScsiSession::RemoveConnection::execute
07:31:34:988 (698) func: >>> iScsiSession::doRemoveConnection
07:31:34:988 (698) func: >>> iScsiTaskList::abortTasks
07:31:34:988 (698) T[0]: Task aborted.
07:31:34:988 (698) func: <<< iScsiTaskList::abortTasks
07:31:34:988 (698) func: >>> iScsiSession::removeConnection
07:31:34:988 (698) func: <<< iScsiSession::removeConnection
07:31:34:988 (698) func: >>> iScsiSession::initiateShutdown
07:31:34:988 (698) S[0x2222]: Stopping 'execute' and all 'recv' and 'send' threads belonging to this session...
07:31:34:988 (698) func: <<< iScsiSession::initiateShutdown
07:31:34:988 (698) func: >>> iScsiServer::removeConnection
07:31:34:988 (698) func: <<< iScsiServer::removeConnection
07:31:34:988 (698) func: <<< iScsiSession::doRemoveConnection
07:31:34:988 (698) func: <<< iScsiSession::RemoveConnection::execute
07:31:34:988 (698) func: >>> iScsiSession::Command::execute
07:31:34:988 (698) func: <<< iScsiSession::Command::execute
07:31:34:988 (698) func: >>> iScsiSession::waitForShutdownComplete
07:31:34:988 (698) func: >>> iScsiServer::removeSession
07:31:34:988 (698) func: <<< iScsiServer::removeSession
07:31:34:988 (698) S: iqn.com.test500mb: 0 session(s) are opened, 1 more allowed.
07:31:34:988 (698) S[0x2222]: RefCount==0. Deleting the session...
07:31:34:988 (698) S[0x2222]: Session destructor called.
07:31:34:998 (698) func: <<< iScsiSession::waitForShutdownComplete
07:31:34:998 (600) func: <<< iScsiConnection::waitForShutdownComplete
07:31:34:998 (600) C[0x1112], IN_LOGIN: RefCount==0. Deleting the connection...
07:31:34:998 (600) C[0x1112], IN_LOGIN: Connection destructor called.
07:35:39:860 (6e4) Srv: Accepted connection from 150.200.3.9:32783. id assigned - 4371
07:35:39:860 (6e4) func: >>> iScsiServer::addConnection
07:35:39:860 (6e4) func: <<< iScsiServer::addConnection
07:35:39:860 (6e4) func: >>> iScsiConnection::start
07:35:39:860 (6e4) func: >>> iScsiServer::removeConnection
07:35:39:860 (6e4) func: <<< iScsiServer::removeConnection
07:35:39:860 (6e4) func: >>> iScsiSession::addConnection
07:35:39:860 (6e4) func: <<< iScsiSession::addConnection
07:35:39:860 (6e4) func: >>> iScsiServer::addSession
07:35:39:860 (6e4) func: <<< iScsiServer::addSession
07:35:39:860 (6e4) func: >>> iScsiConnection::doTransition
07:35:39:860 (6e4) C[0x1113], FREE: Event - CONNECTED.
07:35:39:860 (6e4) C[0x1113], XPT_UP: T3.
07:35:39:860 (6e4) func: <<< iScsiConnection::doTransition
07:35:39:860 (6e4) func: >>> iScsiSession::start
07:35:39:860 (6e4) func: <<< iScsiSession::start
07:35:39:860 (6e4) func: <<< iScsiConnection::start
07:35:39:860 (718) C[0x1113], XPT_UP: Recv thread priority: 1
07:35:39:860 (718) func: >>> iScsiConnection::receive
07:35:39:860 (718) func: >>> iScsiConnection::recvData
07:35:39:860 (78) C[0x1113], XPT_UP: Send thread priority: 0
07:35:39:860 (76c) S[0x2223]: Session exec thread priority: 2
07:35:40:861 (718) func: <<< iScsiConnection::recvData
07:35:40:961 (718) func: >>> iScsiConnection::handleFirstLogin
07:35:40:961 (718) C[0x1113], XPT_UP: Login request: ISID 0x800000000001, TSIH 0x0000.
07:35:40:961 (718) func: >>> iScsiConnection::handlePdu
07:35:40:961 (718) C[0x1113], XPT_UP: >> PDU: Opcode 3, I: ITT 0x0, CmdSn 201326091, ExpStatSN 0; T: ExpCmdSN 201326091, MaxCmdSN 201326290.
07:35:40:961 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:961 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:961 (718) C[0x1113], XPT_UP: New task has been created (0): ITT 0x0.
07:35:40:961 (718) func: >>> iScsiTask::handlePdu
07:35:40:961 (718) func: >>> iScsiTask::handleFirstLoginReq
07:35:40:961 (718) func: >>> iScsiParams::allocateDefault
07:35:40:961 (718) func: <<< iScsiParams::allocateDefault
07:35:40:961 (718) func: >>> iScsiConnection::doTransition
07:35:40:961 (718) C[0x1113], XPT_UP: Event - LOGIN.
07:35:40:961 (718) C[0x1113], IN_LOGIN: T4.
07:35:40:961 (718) func: <<< iScsiConnection::doTransition
07:35:40:961 (718) func: >>> iScsiTask::recvLoginText
07:35:40:961 (718) func: >>> iScsiConnection::recvData
07:35:40:961 (718) func: <<< iScsiConnection::recvData
07:35:40:961 (718) func: <<< iScsiTask::recvLoginText
07:35:40:961 (718) func: >>> iScsiParams::updateFromString
07:35:40:961 (718) Params: <<< String param 'InitiatorName': received 'iqn.0.goldenbwd.hostid.7f000001', accepted 'iqn.0.goldenbwd.hostid.7f000001'
07:35:40:961 (718) Params: <<< String param 'TargetName': received 'iqn.com.test500mb', accepted 'iqn.com.test500mb'
07:35:40:961 (718) Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
07:35:40:961 (718) Params: <<< Numeric param 'MaxConnections': received 1, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'InitialR2T': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Numeric param 'FirstBurstLength': received 65536, accepted 65536
07:35:40:961 (718) Params: <<< Boolean param 'ImmediateData': received No, accepted 0
07:35:40:961 (718) Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 524288, accepted 524288
07:35:40:961 (718) Params: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
07:35:40:961 (718) Params: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
07:35:40:961 (718) Params: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
07:35:40:961 (718) Params: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
07:35:40:961 (718) Params: Update OFMarkInt according to the value of OFMarker.
07:35:40:961 (718) Params: Update IFMarkInt according to the value of IFMarker.
07:35:40:961 (718) func: <<< iScsiParams::updateFromString
07:35:40:961 (718) func: >>> iScsiTask::startLoginPhase
07:35:40:961 (718) S: iqn.com.test500mb: 1 session(s) are opened, 0 more allowed.
07:35:40:961 (718) func: <<< iScsiTask::startLoginPhase
07:35:40:961 (718) func: >>> iScsiTask::handleAuth
07:35:40:961 (718) T[0x0]: Anonymous connection allowed.
07:35:40:961 (718) func: <<< iScsiTask::handleAuth
07:35:40:961 (718) func: >>> iScsiParams::createKeys
07:35:40:961 (718) Params: >>> ErrorRecoveryLevel=0.
07:35:40:961 (718) Params: >>> MaxConnections=1.
07:35:40:961 (718) Params: >>> InitialR2T=Yes.
07:35:40:961 (718) Params: >>> ImmediateData=No.
07:35:40:961 (718) Params: >>> MaxRecvDataSegmentLength=65536.
07:35:40:961 (718) Params: >>> DefaultTime2Wait=2.
07:35:40:961 (718) Params: >>> DefaultTime2Retain=0.
07:35:40:961 (718) Params: >>> MaxOutstandingR2T=1.
07:35:40:961 (718) Params: >>> DataPDUInOrder=Yes.
07:35:40:961 (718) Params: >>> DataSequenceInOrder=Yes.
07:35:40:961 (718) Params: >>> TargetPortalGroupTag=1.
07:35:40:961 (718) func: <<< iScsiParams::createKeys
07:35:40:961 (718) func: >>> iScsiTask::setState
07:35:40:961 (718) T[0x0]: setState 0x30.
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326091, ITT 0x0.
07:35:40:971 (76c) func: >>> iScsiTask::execute
07:35:40:971 (76c) func: >>> iScsiTask::execLoginReq
07:35:40:971 (76c) T[0x0]: The end of stage 1, next stage is 3.
07:35:40:971 (76c) func: >>> iScsiConnection::doTransition
07:35:40:971 (76c) C[0x1113], IN_LOGIN: Event - LOGIN_ACCEPT.
07:35:40:971 (76c) C[0x1113], LOGGED_IN: T5.
07:35:40:971 (76c) func: <<< iScsiConnection::doTransition
07:35:40:971 (76c) func: >>> iScsiConnection::applyParams
07:35:40:971 (76c) func: <<< iScsiConnection::applyParams
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x0]: setState 0x700.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: <<< iScsiTask::execLoginReq
07:35:40:971 (76c) func: <<< iScsiTask::execute
07:35:40:971 (76c) func: <<< iScsiSession::execute
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleFirstLoginReq
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handleFirstLogin
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::recvData
07:35:40:971 (78) func: >>> iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiTask::sendBufsCount
07:35:40:971 (78) func: <<< iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::sendFillBufs
07:35:40:971 (78) T[0x0]: << PDU: OpCode 35, StatSN 0, ExpCmdSN 201326091, MaxCmdSN 201326290.
07:35:40:971 (78) func: <<< iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiTask::setState
07:35:40:971 (78) T[0x0]: setState 0x1000.
07:35:40:971 (78) func: <<< iScsiTask::setState
07:35:40:971 (78) func: <<< iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiTaskList::freeCompleted
07:35:40:971 (718) func: <<< iScsiConnection::recvData
07:35:40:971 (718) func: >>> iScsiConnection::handlePdu
07:35:40:971 (718) C[0x1113], LOGGED_IN: >> PDU: Opcode 1, I: ITT 0x0, CmdSn 201326091, ExpStatSN 1; T: ExpCmdSN 201326091, MaxCmdSN 201326290.
07:35:40:971 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:971 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:971 (718) C[0x1113], LOGGED_IN: New task has been created (1): ITT 0x0.
07:35:40:971 (718) func: >>> iScsiTask::handlePdu
07:35:40:971 (718) func: >>> iScsiTask::handleScsiCmd
07:35:40:971 (718) T[0x0]: ISCSI_TASK_CREATED: initializing task structure.
07:35:40:971 (718) T[0x0]: SCSI command: LUN 0x0, opcode 0x12, attrs 0x01, read 255 bytes, write 0 bytes.
12 00 00 00 ff 00 00 00 00 00 00 00 00 00 00 00
07:35:40:971 (718) T[0x0]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (718) func: >>> iScsiSscDevice::prepare
07:35:40:971 (718) SCSI: SscPort_Prepare supported.
07:35:40:971 (718) func: <<< iScsiSscDevice::prepare
07:35:40:971 (718) func: >>> iScsiTask::setState
07:35:40:971 (718) T[0x0]: setState 0x20.
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326091, ITT 0x0.
07:35:40:971 (76c) func: >>> iScsiTask::execute
07:35:40:971 (76c) func: >>> iScsiTask::execScsiCmd
07:35:40:971 (76c) T[0x0]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x0]: setState 0x40.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: >>> iScsiSscDevice::dispatch
ImageFile[76c]->ImageFile_ScsiExec >>
ImageFile[76c] ImageFile_ScsiExec: (0xD31A0), CDB: 12 00 00 00 FF 00 00 00 00 00 00 00
ImageFile[76c] ImageFile_ScsiExec: SCSIOP_INQUIRY...
ImageFile[76c]->ImageFile_ScsiCompleteRequest >>
07:35:40:971 (76c) func: >>> iScsiTask::dispatchCompleted
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x0]: setState 0x600.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: <<< iScsiTask::dispatchCompleted
ImageFile[76c]<-ImageFile_ScsiCompleteRequest <<
07:35:40:971 (76c) func: <<< iScsiSscDevice::dispatch
07:35:40:971 (76c) func: <<< iScsiTask::execScsiCmd
07:35:40:971 (76c) func: <<< iScsiTask::execute
07:35:40:971 (76c) func: <<< iScsiSession::execute
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleScsiCmd
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::recvData
07:35:40:971 (78) func: <<< iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::dataInBufsCount
07:35:40:971 (78) T[0x0]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288.
07:35:40:971 (78) T[0x0]: DataTransferLength 96, PDUs 1, padding 0.
07:35:40:971 (78) T[0x0]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x0]: WSABUF.len 96.
07:35:40:971 (78) func: <<< iScsiTask::dataInBufsCount
07:35:40:971 (78) func: <<< iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::prepareDataIn
07:35:40:971 (78) T[0x0]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288, DataTransferLength 96, PDUs 1.
07:35:40:971 (78) T[0x0]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x0]: WSABUF.len 96.
07:35:40:971 (78) T[0x0]: End of DATA-IN PDU.
07:35:40:971 (78) T[0x0]: End of sequence.
07:35:40:971 (78) T[0x0]: End of DATA-IN PDUs.
07:35:40:971 (78) T[0x0]: Data-in: ITT 0x0, TTT 0x4, ExpCmdSN 201326092, MaxCmdSN 201326290, DataSN 0, Offset 0, Length 96, F 1.
07:35:40:971 (78) func: <<< iScsiTask::prepareDataIn
07:35:40:971 (78) func: <<< iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiSscDevice::complete
07:35:40:971 (78) SCSI: SscPort_CommandCompleted supported.
07:35:40:971 (78) func: <<< iScsiSscDevice::complete
07:35:40:971 (718) func: <<< iScsiConnection::recvData
07:35:40:971 (718) func: >>> iScsiConnection::handlePdu
07:35:40:971 (718) C[0x1113], LOGGED_IN: >> PDU: Opcode 1, I: ITT 0x1, CmdSn 201326092, ExpStatSN 2; T: ExpCmdSN 201326092, MaxCmdSN 201326290.
07:35:40:971 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:971 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:971 (718) C[0x1113], LOGGED_IN: New task has been created (2): ITT 0x1.
07:35:40:971 (718) func: >>> iScsiTask::handlePdu
07:35:40:971 (718) func: >>> iScsiTask::handleScsiCmd
07:35:40:971 (718) T[0x1]: ISCSI_TASK_CREATED: initializing task structure.
07:35:40:971 (718) T[0x1]: SCSI command: LUN 0x0, opcode 0x00, attrs 0x01, read 0 bytes, write 0 bytes.
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
07:35:40:971 (718) T[0x1]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (718) func: >>> iScsiSscDevice::prepare
07:35:40:971 (718) SCSI: SscPort_Prepare supported.
07:35:40:971 (718) func: <<< iScsiSscDevice::prepare
07:35:40:971 (718) func: >>> iScsiTask::setState
07:35:40:971 (718) T[0x1]: setState 0x20.
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleScsiCmd
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::recvData
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326092, ITT 0x1.
07:35:40:971 (76c) func: >>> iScsiTask::execute
07:35:40:971 (76c) func: >>> iScsiTask::execScsiCmd
07:35:40:971 (76c) T[0x1]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x1]: setState 0x40.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: >>> iScsiSscDevice::dispatch
ImageFile[76c]->ImageFile_ScsiExec >>
ImageFile[76c] ImageFile_ScsiExec: (0xD3308), CDB: 00 00 00 00 00 00 00 00 00 00 00 00
ImageFile[76c] ImageFile_ScsiExec: SCSIOP_TEST_UNIT_READY...
ImageFile[76c]->ImageFile_ScsiCompleteRequest >>
07:35:40:971 (76c) func: >>> iScsiTask::dispatchCompleted
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x1]: setState 0x600.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: <<< iScsiTask::dispatchCompleted
ImageFile[76c]<-ImageFile_ScsiCompleteRequest <<
07:35:40:971 (76c) func: <<< iScsiSscDevice::dispatch
07:35:40:971 (76c) func: <<< iScsiTask::execScsiCmd
07:35:40:971 (76c) func: <<< iScsiTask::execute
07:35:40:971 (76c) func: <<< iScsiSession::execute
07:35:40:971 (78) func: >>> iScsiTask::setState
07:35:40:971 (78) T[0x0]: setState 0x1000.
07:35:40:971 (78) func: <<< iScsiTask::setState
07:35:40:971 (78) func: <<< iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::dataInBufsCount
07:35:40:971 (78) func: <<< iScsiTask::dataInBufsCount
07:35:40:971 (78) func: <<< iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::prepareCmdRsp
07:35:40:971 (78) T[0x1]: SCSI rsp: status 0x00, response 0x00, ouOU 0000, ITT 0x1.
07:35:40:971 (78) T[0x1]: << PDU: OpCode 33, StatSN 2, ExpCmdSN 201326093, MaxCmdSN 201326291.
07:35:40:971 (78) func: <<< iScsiTask::prepareCmdRsp
07:35:40:971 (78) func: <<< iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiSscDevice::complete
07:35:40:971 (78) SCSI: SscPort_CommandCompleted supported.
07:35:40:971 (718) func: <<< iScsiConnection::recvData
07:35:40:971 (718) func: >>> iScsiConnection::handlePdu
07:35:40:971 (718) C[0x1113], LOGGED_IN: >> PDU: Opcode 1, I: ITT 0x2, CmdSn 201326093, ExpStatSN 3; T: ExpCmdSN 201326093, MaxCmdSN 201326291.
07:35:40:971 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:971 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:971 (718) C[0x1113], LOGGED_IN: New task has been created (3): ITT 0x2.
07:35:40:971 (718) func: >>> iScsiTask::handlePdu
07:35:40:971 (718) func: >>> iScsiTask::handleScsiCmd
07:35:40:971 (718) T[0x2]: ISCSI_TASK_CREATED: initializing task structure.
07:35:40:971 (718) T[0x2]: SCSI command: LUN 0x0, opcode 0x12, attrs 0x01, read 255 bytes, write 0 bytes.
12 00 00 00 ff 00 00 00 00 00 00 00 00 00 00 00
07:35:40:971 (718) T[0x2]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (718) func: >>> iScsiSscDevice::prepare
07:35:40:971 (718) SCSI: SscPort_Prepare supported.
07:35:40:971 (718) func: <<< iScsiSscDevice::prepare
07:35:40:971 (718) func: >>> iScsiTask::setState
07:35:40:971 (718) T[0x2]: setState 0x20.
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleScsiCmd
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::recvData
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326093, ITT 0x2.
07:35:40:971 (76c) func: >>> iScsiTask::execute
07:35:40:971 (76c) func: >>> iScsiTask::execScsiCmd
07:35:40:971 (76c) T[0x2]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x2]: setState 0x40.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: >>> iScsiSscDevice::dispatch
ImageFile[76c]->ImageFile_ScsiExec >>
ImageFile[76c] ImageFile_ScsiExec: (0xD3470), CDB: 12 00 00 00 FF 00 00 00 00 00 00 00
ImageFile[76c] ImageFile_ScsiExec: SCSIOP_INQUIRY...
ImageFile[76c]->ImageFile_ScsiCompleteRequest >>
07:35:40:971 (76c) func: >>> iScsiTask::dispatchCompleted
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x2]: setState 0x600.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: <<< iScsiTask::dispatchCompleted
ImageFile[76c]<-ImageFile_ScsiCompleteRequest <<
07:35:40:971 (76c) func: <<< iScsiSscDevice::dispatch
07:35:40:971 (76c) func: <<< iScsiTask::execScsiCmd
07:35:40:971 (76c) func: <<< iScsiTask::execute
07:35:40:971 (76c) func: <<< iScsiSession::execute
07:35:40:971 (78) func: <<< iScsiSscDevice::complete
07:35:40:971 (78) func: >>> iScsiTask::setState
07:35:40:971 (78) T[0x1]: setState 0x1000.
07:35:40:971 (78) func: <<< iScsiTask::setState
07:35:40:971 (78) func: <<< iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::dataInBufsCount
07:35:40:971 (78) T[0x2]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288.
07:35:40:971 (78) T[0x2]: DataTransferLength 96, PDUs 1, padding 0.
07:35:40:971 (78) T[0x2]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x2]: WSABUF.len 96.
07:35:40:971 (78) func: <<< iScsiTask::dataInBufsCount
07:35:40:971 (78) func: <<< iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::prepareDataIn
07:35:40:971 (78) T[0x2]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288, DataTransferLength 96, PDUs 1.
07:35:40:971 (78) T[0x2]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x2]: WSABUF.len 96.
07:35:40:971 (78) T[0x2]: End of DATA-IN PDU.
07:35:40:971 (78) T[0x2]: End of sequence.
07:35:40:971 (78) T[0x2]: End of DATA-IN PDUs.
07:35:40:971 (78) T[0x2]: Data-in: ITT 0x2, TTT 0x8, ExpCmdSN 201326094, MaxCmdSN 201326292, DataSN 0, Offset 0, Length 96, F 1.
07:35:40:971 (78) func: <<< iScsiTask::prepareDataIn
07:35:40:971 (78) func: <<< iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiSscDevice::complete
07:35:40:971 (78) SCSI: SscPort_CommandCompleted supported.
07:35:40:971 (78) func: <<< iScsiSscDevice::complete
07:35:40:971 (718) func: <<< iScsiConnection::recvData
07:35:40:971 (718) func: >>> iScsiConnection::handlePdu
07:35:40:971 (718) C[0x1113], LOGGED_IN: >> PDU: Opcode 1, I: ITT 0x3, CmdSn 201326094, ExpStatSN 4; T: ExpCmdSN 201326094, MaxCmdSN 201326292.
07:35:40:971 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:971 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:971 (718) C[0x1113], LOGGED_IN: New task has been created (4): ITT 0x3.
07:35:40:971 (718) func: >>> iScsiTask::handlePdu
07:35:40:971 (718) func: >>> iScsiTask::handleScsiCmd
07:35:40:971 (718) T[0x3]: ISCSI_TASK_CREATED: initializing task structure.
07:35:40:971 (718) T[0x3]: SCSI command: LUN 0x0, opcode 0x12, attrs 0x01, read 255 bytes, write 0 bytes.
12 01 c7 00 ff 00 00 00 00 00 00 00 00 00 00 00
07:35:40:971 (718) T[0x3]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (718) func: >>> iScsiSscDevice::prepare
07:35:40:971 (718) SCSI: SscPort_Prepare supported.
07:35:40:971 (718) func: <<< iScsiSscDevice::prepare
07:35:40:971 (718) func: >>> iScsiTask::setState
07:35:40:971 (718) T[0x3]: setState 0x20.
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326094, ITT 0x3.
07:35:40:971 (76c) func: >>> iScsiTask::execute
07:35:40:971 (76c) func: >>> iScsiTask::execScsiCmd
07:35:40:971 (76c) T[0x3]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x3]: setState 0x40.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: >>> iScsiSscDevice::dispatch
ImageFile[76c]->ImageFile_ScsiExec >>
ImageFile[76c] ImageFile_ScsiExec: (0xD35D8), CDB: 12 01 C7 00 FF 00 00 00 00 00 00 00
ImageFile[76c] ImageFile_ScsiExec: SCSIOP_INQUIRY...
ImageFile[76c]->ImageFile_ScsiCompleteRequest >>
07:35:40:971 (76c) func: >>> iScsiTask::dispatchCompleted
07:35:40:971 (76c) func: >>> iScsiTask::setState
07:35:40:971 (76c) T[0x3]: setState 0x600.
07:35:40:971 (76c) func: <<< iScsiTask::setState
07:35:40:971 (76c) func: <<< iScsiTask::dispatchCompleted
ImageFile[76c]<-ImageFile_ScsiCompleteRequest <<
07:35:40:971 (76c) func: <<< iScsiSscDevice::dispatch
07:35:40:971 (76c) func: <<< iScsiTask::execScsiCmd
07:35:40:971 (76c) func: <<< iScsiTask::execute
07:35:40:971 (76c) func: <<< iScsiSession::execute
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleScsiCmd
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::receive
07:35:40:971 (718) func: >>> iScsiConnection::recvData
07:35:40:971 (78) func: >>> iScsiTask::setState
07:35:40:971 (78) T[0x2]: setState 0x1000.
07:35:40:971 (78) func: <<< iScsiTask::setState
07:35:40:971 (78) func: <<< iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiTaskList::freeCompleted
07:35:40:971 (78) func: <<< iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiConnection::send
07:35:40:971 (78) func: >>> iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::dataInBufsCount
07:35:40:971 (78) T[0x3]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288.
07:35:40:971 (78) T[0x3]: DataTransferLength 96, PDUs 1, padding 0.
07:35:40:971 (78) T[0x3]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x3]: WSABUF.len 96.
07:35:40:971 (78) func: <<< iScsiTask::dataInBufsCount
07:35:40:971 (78) func: <<< iScsiTask::sendBufsCount
07:35:40:971 (78) func: >>> iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::prepareDataIn
07:35:40:971 (78) T[0x3]: MaxBurstLength 262144, MaxRecvDataSegmentLength 524288, DataTransferLength 96, PDUs 1.
07:35:40:971 (78) T[0x3]: Buffers[0].Size 255.
07:35:40:971 (78) T[0x3]: WSABUF.len 96.
07:35:40:971 (78) T[0x3]: End of DATA-IN PDU.
07:35:40:971 (78) T[0x3]: End of sequence.
07:35:40:971 (78) T[0x3]: End of DATA-IN PDUs.
07:35:40:971 (78) T[0x3]: Data-in: ITT 0x3, TTT 0xa, ExpCmdSN 201326095, MaxCmdSN 201326293, DataSN 0, Offset 0, Length 96, F 1.
07:35:40:971 (78) func: <<< iScsiTask::prepareDataIn
07:35:40:971 (78) func: <<< iScsiTask::sendFillBufs
07:35:40:971 (78) func: >>> iScsiTask::sendComplete
07:35:40:971 (78) func: >>> iScsiSscDevice::complete
07:35:40:971 (78) SCSI: SscPort_CommandCompleted supported.
07:35:40:971 (78) func: <<< iScsiSscDevice::complete
07:35:40:971 (78) func: >>> iScsiTask::setState
07:35:40:971 (78) T[0x3]: setState 0x1000.
07:35:40:971 (718) func: <<< iScsiConnection::recvData
07:35:40:971 (718) func: >>> iScsiConnection::handlePdu
07:35:40:971 (718) C[0x1113], LOGGED_IN: >> PDU: Opcode 1, I: ITT 0x4, CmdSn 201326095, ExpStatSN 5; T: ExpCmdSN 201326095, MaxCmdSN 201326293.
07:35:40:971 (718) func: >>> iScsiTaskList::allocateTask
07:35:40:971 (718) func: <<< iScsiTaskList::allocateTask
07:35:40:971 (718) C[0x1113], LOGGED_IN: New task has been created (5): ITT 0x4.
07:35:40:971 (718) func: >>> iScsiTask::handlePdu
07:35:40:971 (718) func: >>> iScsiTask::handleScsiCmd
07:35:40:971 (718) T[0x4]: ISCSI_TASK_CREATED: initializing task structure.
07:35:40:971 (718) T[0x4]: SCSI command: LUN 0x0, opcode 0x25, attrs 0x01, read 8 bytes, write 0 bytes.
25 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
07:35:40:971 (718) T[0x4]: Peripheral device addressing LUN: Bus 0, Target 0, Lun 0
07:35:40:971 (718) func: >>> iScsiSscDevice::prepare
07:35:40:971 (718) SCSI: SscPort_Prepare supported.
07:35:40:971 (718) func: <<< iScsiSscDevice::prepare
07:35:40:971 (718) func: >>> iScsiTask::setState
07:35:40:971 (718) T[0x4]: setState 0x20.
07:35:40:971 (718) func: <<< iScsiTask::setState
07:35:40:971 (718) func: <<< iScsiTask::handleScsiCmd
07:35:40:971 (718) func: <<< iScsiTask::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::handlePdu
07:35:40:971 (718) func: <<< iScsiConnection::receive
07:35:40:971 (76c) func: >>> iScsiSession::execute
07:35:40:971 (76c) S[0x2223]: Executing task: CmdSN 201326095, ITT 0x4.
07:35:40:971 (76c) func: >>> iScsiTask::execute
Val (staff)
Posts: 496
Joined: Tue Jun 29, 2004 8:38 pm

Tue Feb 08, 2005 11:57 am

Hi!

I've tried Starwind and am very pleased with its performance with Windows clients so far.

I'm evaluating Starwind for a client that has an IBM Power 5 e-server model 550 running 64 bit AIX ver. 5.3L which includes a native iSCSI driver for its GigE and 100Mbit ethernet NICs.

Even after updating the AIX OS and all its drivers to the latest available, we are still not able to connect to the Starwind iscsi server. Before we updated to the latest AIX OS level, we could not get even a hint of a connection. After the update, the AIX device list now shows an iscsi "hdisk1" with a "defined" label. For this to be accessible to the IBM server, its status label should be "available" and then a filesystem can be installed and mounted.

We tried all variations we could think of, but "defined" is the only status we got.

It looks like a connection is negotiated but just as quickly closed.

Following is the level 3 log. We would appreciate it if someone could take a look at it and suggest how we can make this work?
Hi JOE-O,

We have no experience with AIX iSCSI initiators yet.
But according to the logs it looks like the AIX initiator does not negotiate all the ISCSI options that must be negotiated.

Does the AIX initiator compatible with iSCSI v1.0 (RFC 3720) (formely iSCSI draft 20) ?

The initiator from IP 150.200.3.14 did not negtitate FirstBurstLength, so StarWind rejected it.

The initiator from IP 150.200.3.9 seems to negotiate and login OK and it ever successfully executed several INQUIRY requests and read the first disk sector.
So the iSCSI session was established and worked well.

FYI a new ImageFile disk is not initialized (it completely filled with zeros).
In Windows a new disk need to be initialized with Disk Manager before it is recognized by the system.

Maybe your AIX OS also need the disk to be initialized manually before it is accessible from the AIX system?
Best regards,
Valeriy
JOE-O
Posts: 2
Joined: Mon Feb 07, 2005 1:09 pm
Location: Philippines

Tue Feb 08, 2005 3:24 pm

Hi Valery,

Thank you for taking a look at this problem.

Please tell us the complete minimum list of iscsi options to be negotiated for a successful connection.

according to the IBM documentation,

"The iSCSI software initiator allows AIX to access storage devices using TCP/IP on Ethernet network adapters. The iSCSI software initiator implements the iSCSI protocol as defined in iSCSI IETF draft-20."

Here's the link to the documentation: http://publib16.boulder.ibm.com/pseries ... tiator.htm

Please see if the section on "Additional considerations" in that link might have information related to our problem and advise us how we might attempt to make a successful connection.

From your reply, you said that The initiator from IP 150.200.3.9 appears to have made a successful connection that worked well. This is true, but the connection was only for a split second, then was lost. Does the log show how long the session lasted and why it disconnected? That quick connect and immediate disconnect is why AIX reported the iscsi disk it saw as "defined" but not "available". If the connection was not lost, it would be "available" and ready to be initialized with the AIX filesystem.

We made the 500MB imagefile as unformatted so it could be formatted by client OS with a filesystem of choice. We tried this with a Windows client and the starwind target was recognized as an unformatted disk and allowed us to format it any way we wanted.

Hope you can check that link and suggest what we can do to make it work.

Thanking you again,

Joe-O
Val (staff)
Posts: 496
Joined: Tue Jun 29, 2004 8:38 pm

Tue Feb 08, 2005 4:14 pm

JOE-O wrote:Hi Valery,

Thank you for taking a look at this problem.

Please tell us the complete minimum list of iscsi options to be negotiated for a successful connection.

according to the IBM documentation,

"The iSCSI software initiator allows AIX to access storage devices using TCP/IP on Ethernet network adapters. The iSCSI software initiator implements the iSCSI protocol as defined in iSCSI IETF draft-20."

Here's the link to the documentation: http://publib16.boulder.ibm.com/pseries ... tiator.htm

Please see if the section on "Additional considerations" in that link might have information related to our problem and advise us how we might attempt to make a successful connection.

From your reply, you said that The initiator from IP 150.200.3.9 appears to have made a successful connection that worked well. This is true, but the connection was only for a split second, then was lost. Does the log show how long the session lasted and why it disconnected? That quick connect and immediate disconnect is why AIX reported the iscsi disk it saw as "defined" but not "available". If the connection was not lost, it would be "available" and ready to be initialized with the AIX filesystem.

We made the 500MB imagefile as unformatted so it could be formatted by client OS with a filesystem of choice. We tried this with a Windows client and the starwind target was recognized as an unformatted disk and allowed us to format it any way we wanted.

Hope you can check that link and suggest what we can do to make it work.

Thanking you again,

Joe-O
Hi Joe-O,

The following strings from the log show which iSCSI parameters are negotiated.
07:35:40:961 (718) Params: <<< String param 'InitiatorName': received 'iqn.0.goldenbwd.hostid.7f000001', accepted 'iqn.0.goldenbwd.hostid.7f000001'
07:35:40:961 (718) Params: <<< String param 'TargetName': received 'iqn.com.test500mb', accepted 'iqn.com.test500mb'
07:35:40:961 (718) Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
07:35:40:961 (718) Params: <<< Numeric param 'MaxConnections': received 1, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'InitialR2T': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Numeric param 'FirstBurstLength': received 65536, accepted 65536
07:35:40:961 (718) Params: <<< Boolean param 'ImmediateData': received No, accepted 0
07:35:40:961 (718) Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 524288, accepted 524288
07:35:40:961 (718) Params: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
07:35:40:961 (718) Params: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
07:35:40:961 (718) Params: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
07:35:40:961 (718) Params: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
07:35:40:961 (718) Params: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
.....
07:35:40:961 (718) func: >>> iScsiParams::createKeys
07:35:40:961 (718) Params: >>> ErrorRecoveryLevel=0.
07:35:40:961 (718) Params: >>> MaxConnections=1.
07:35:40:961 (718) Params: >>> InitialR2T=Yes.
07:35:40:961 (718) Params: >>> ImmediateData=No.
07:35:40:961 (718) Params: >>> MaxRecvDataSegmentLength=65536.
07:35:40:961 (718) Params: >>> DefaultTime2Wait=2.
07:35:40:961 (718) Params: >>> DefaultTime2Retain=0.
07:35:40:961 (718) Params: >>> MaxOutstandingR2T=1.
07:35:40:961 (718) Params: >>> DataPDUInOrder=Yes.
07:35:40:961 (718) Params: >>> DataSequenceInOrder=Yes.
07:35:40:961 (718) Params: >>> TargetPortalGroupTag=1.
I've just reviewed the log once more.
It seemsit is not completed one. The tail is missing.
I can see only INQUIRY requests and the beginning of a READ_CAPACITY (Opcode 0x25).

Could you please provide me with a full log file where all the session is shown?
(You can send it to my email)
Best regards,
Valeriy
Locked