Possible issue with Max Frame size and Starwind

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

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

Locked
Codiak6335

Fri Aug 06, 2004 6:39 am

Using Starwind and StarPort, identical Linksys 10/100/1000 nics I increased the Max Frame Size from the legacy default of 1514 to 9000 on both machines. Starport connects, but there is a media error as soon as I try to access the device. I played around a bit and it appears to be related to Starwind. (logs attached) If I leave target at 1514 and the initiator at 9000 all is well... as soon as I alter the target the problem occurs.



06:29:49:968 (2136) conf: Reading '[parameters]'
06:29:49:968 (2136) conf: 'LogLevel' = '3'
06:29:49:968 (2136) conf: 'LogMask' = '0x8000ffff'
06:29:49:968 (2136) conf: 'Port' = '3260'
06:29:49:968 (2136) conf: 'Interface' = '0.0.0.0'
06:29:49:968 (2136) conf: 'DefTargetName' = 'iqn.2003-06.com.rocketdivision.starwind:$(host).$(symid)'
06:29:49:968 (2136) conf: 'Login' = 'test'
06:29:49:968 (2136) conf: 'Password' = 'test'
06:29:49:968 (2136) conf: 'Echo' = 'no'
06:29:49:968 (2136) conf: 'MinBufferSize' = '65536'
06:29:49:968 (2136) conf: 'AlignmentMask' = '0x0000'
06:29:49:968 (2136) conf: 'MaxPendingRequests' = '64'
06:29:49:968 (2136) conf: Reading '[plugins]'
06:29:49:984 (2136) conf: Reading '[devices]'
06:29:49:984 (2136) conf: Reading '[permissions]'
RamDisk[858] *SscPort_Init: Logging level is set to 3.
RamDisk[858] *SscPort_Init:
VendorId = ' '
ProductId = ' '
Revision = '0001'
06:29:49:984 (2136) func: >>> iScsiServer::addPlugin
06:29:49:984 (2136) func: <<< iScsiServer::addPlugin
06:29:49:984 (2136) conf: 'RamDisk.dll' loaded successfully.
ImageFile[858] *SscPort_Init: Logging level is set to 3.
ImageFile[858] *SscPort_Init:
VendorId = ' '
ProductId = ' '
Revision = '0001'
ImageDir = 'images\'
ImageMask = '*.img'
ExeDir = 'C:\Program Files\Rocket Division Software\StarWind\'
06:29:49:984 (2136) func: >>> iScsiServer::addPlugin
06:29:49:984 (2136) func: <<< iScsiServer::addPlugin
06:29:49:984 (2136) conf: 'ImageFile.dll' loaded successfully.
VirtualDVD[858] *SscPort_Init: Logging level is set to 3.
VirtualDVD[858] *SscPort_Init:
VendorId = 'ROCKET '
ProductId = 'DVD-ROM F50 '
Revision = '1.00'
06:29:49:984 (2136) func: >>> iScsiServer::addPlugin
06:29:49:984 (2136) func: <<< iScsiServer::addPlugin
06:29:49:984 (2136) conf: 'VirtualDvd.dll' loaded successfully.
06:29:49:984 (2136) func: >>> iScsiServer::addDevice
06:29:49:984 (2136) func: <<< iScsiServer::addDevice
06:29:49:984 (2136) S: Assigned target name: 'iqn.2003-06.com.rocketdivision.starwind:amd64test.ramdrive0', SymId: 'RamDrive0'.
06:29:49:984 (2136) func: >>> iScsiSscDevice::open
RamDisk[858] *SscPort_Create: RamDisk: opening device 'RamDrive0', size 16, format yes.
RamDisk[858] *RamDisk_Create: Creating Ram Disk: 16 MB (32768 sectors)...
RamDisk[858] *RamDisk_Create: RamDisk_Create(): Disk geometry: Sect/Track= 16, Tracks/Cyl= 32, Ncyl= 64, TotalSectors: 32768
RamDisk[858] *RamDisk_Create: RamDisk_Create(): 4096 AWE pages were allocated.
RamDisk[858] *RamDisk_Create: RamDisk_Create(): 0 memory blocks were allocated.
RamDisk[858] RamDisk_WriteSectorsAwe: Write AWE pages: dwStartSector 0, dwSectorsToWrite 1, pBuffer 97028, dwBufferSize 512.
RamDisk[858] RamDisk_WriteSectorsAwe: Map region: MappedPage 0, NumberOfMappedPages 2048
.RamDisk[858] *RamDisk_FormatDisk: RamDisk to format: Cylinders: 64, TracksPerCylinder: 32, SectorsPerTrack: 16, BytesPerSector: 512
RamDisk[858] *RamDisk_FormatDisk: Ramdisk formatting: Root dir entries: 128, Sectors/cluster: 1
RamDisk[858] RamDisk_WriteSectorsAwe: Write AWE pages: dwStartSector 16, dwSectorsToWrite 1, pBuffer 97028, dwBufferSize 512.
RamDisk[858] RamDisk_WriteSectorsAwe: Using the current region: MappedPage 0, Offset 0 -> 8192
.RamDisk[858] RamDisk_WriteSectorsAwe: Write AWE pages: dwStartSector 17, dwSectorsToWrite 128, pBuffer 97230, dwBufferSize 65536.
RamDisk[858] RamDisk_WriteSectorsAwe: Using the current region: MappedPage 0, Offset 512 -> 8704
.RamDisk[858] RamDisk_WriteSectorsAwe: Write AWE pages: dwStartSector 145, dwSectorsToWrite 1, pBuffer a7238, dwBufferSize 512.
RamDisk[858] RamDisk_WriteSectorsAwe: Using the current region: MappedPage 0, Offset 512 -> 74240
.RamDisk[858]->RamDisk_BuildInquiry >>
RamDisk[858] *RamDisk_BuildInquiry: Use default VendorId
RamDisk[858] *RamDisk_BuildInquiry: Use default ProductId
RamDisk[858] *RamDisk_BuildInquiry:
VendorId = 'ROCKET '
ProductId = 'RAM DISK 16 MB '
Revision = '0001'
RamDisk[858]<-RamDisk_BuildInquiry << Return (0x0)
06:29:49:984 (2136) func: <<< iScsiSscDevice::open
06:29:49:984 (2136) S: the device 'RamDrive0' is opened successfully.
06:29:49:984 (2136) S: parameter 'size', value '16'.
06:29:49:984 (2136) S: parameter 'format', value 'yes'.
06:29:49:984 (2136) S: iqn.2003-06.com.rocketdivision.starwind:amd64test.ramdrive0: 1 session(s) allowed.
06:29:49:984 (2136) conf: Target [0] has been created. Device 'RamDrive0' is accesible as target 'iqn.2003-06.com.rocketdivision.starwind:amd64test.ramdrive0'.
06:29:49:984 (2136) func: >>> iScsiServer::addDevice
06:29:49:984 (2136) func: <<< iScsiServer::addDevice
06:29:49:984 (2136) S: Assigned target name: 'winnn1', SymId: 'Physicaldrive1'.
06:29:49:984 (2136) func: >>> iScsiSptiDevice::open
06:29:49:984 (2136) func: >>> iScsiSptiDevice::probe
06:29:49:984 (2136) func: <<< iScsiSptiDevice::probe
06:29:49:984 (2136) SPTI: '\\.\Physicaldrive1': 'VIA SATA RAID 1 ': adapter 2, bus 0, target id 0, LUN 0; maxTransferLength 65536
06:29:49:984 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:49:984 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:49:984 (2136) func: <<< iScsiSptiDevice::open
06:29:49:984 (2136) S: the device '\\.\Physicaldrive1' is opened successfully.
06:29:49:984 (2136) S: winnn1: 1 session(s) allowed.
06:29:49:984 (2136) conf: Target [1] has been created. Device '\\.\Physicaldrive1' is accesible as target 'winnn1'.
06:29:49:984 (2136) func: >>> iScsiServer::refreshDeviceList
06:29:49:984 (2136) Srv: Refreshing device list...
06:29:50:078 (2136) func: >>> iScsiSptiDevice::open
06:29:50:171 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:171 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:187 (2136) SPTI: '\\.\D:': Cannot get SCSI address for the device: The request is not supported. (code: 50).
06:29:50:187 (2136) SPTI: '\\.\D:': 'USB2.0 CF CardReader ': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 65536
06:29:50:187 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:203 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:203 (2136) func: <<< iScsiSptiDevice::open
06:29:50:203 (2136) Srv: '\\.\D:': hard drive may not be accessed through '\\.\<X>:' symlink.
06:29:50:203 (2136) Srv: *ERROR* The device '\\.\D:' is not allowed by the server.
06:29:50:203 (2136) func: >>> iScsiSptiDevice::close
06:29:50:203 (2136) func: <<< iScsiSptiDevice::close
06:29:50:281 (2136) func: >>> iScsiSptiDevice::open
06:29:50:375 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:390 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:390 (2136) SPTI: '\\.\E:': Cannot get SCSI address for the device: The request is not supported. (code: 50).
06:29:50:390 (2136) SPTI: '\\.\E:': 'USB2.0 CBO CardReader ': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 65536
06:29:50:390 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::open
06:29:50:406 (2136) Srv: '\\.\E:': hard drive may not be accessed through '\\.\<X>:' symlink.
06:29:50:406 (2136) Srv: *ERROR* The device '\\.\E:' is not allowed by the server.
06:29:50:406 (2136) func: >>> iScsiSptiDevice::close
06:29:50:406 (2136) func: <<< iScsiSptiDevice::close
06:29:50:406 (2136) func: >>> iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:406 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:406 (2136) SPTI: '\\.\F:': ' GENERIC DVD RW 8XMax 140I': adapter 1, bus 0, target id 0, LUN 0; maxTransferLength 131072
06:29:50:406 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::close
06:29:50:406 (2136) func: <<< iScsiSptiDevice::close
06:29:50:406 (2136) Srv: A new SPTI device '\\.\F:' found.
06:29:50:406 (2136) func: >>> iScsiServer::addDevice
06:29:50:406 (2136) func: <<< iScsiServer::addDevice
06:29:50:406 (2136) func: >>> iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:406 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:406 (2136) SPTI: '\\.\Cdrom0': ' GENERIC DVD RW 8XMax 140I': adapter 1, bus 0, target id 0, LUN 0; maxTransferLength 131072
06:29:50:406 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::open
06:29:50:406 (2136) Srv: '\\.\Cdrom0': SCSI device with the same address is already present in the system.
06:29:50:406 (2136) Srv: *ERROR* The device '\\.\Cdrom0' is not allowed by the server.
06:29:50:406 (2136) func: >>> iScsiSptiDevice::close
06:29:50:406 (2136) func: <<< iScsiSptiDevice::close
06:29:50:406 (2136) func: >>> iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:406 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:406 (2136) SPTI: '\\.\Physicaldrive0': ' HDS722525VLAT80 V36OA60A': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 131072
06:29:50:406 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:406 (2136) func: <<< iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::close
06:29:50:406 (2136) func: <<< iScsiSptiDevice::close
06:29:50:406 (2136) Srv: A new SPTI device '\\.\Physicaldrive0' found.
06:29:50:406 (2136) func: >>> iScsiServer::addDevice
06:29:50:406 (2136) func: <<< iScsiServer::addDevice
06:29:50:406 (2136) func: >>> iScsiSptiDevice::open
06:29:50:406 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:421 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:421 (2136) SPTI: '\\.\Physicaldrive2': Cannot get SCSI address for the device: The request is not supported. (code: 50).
06:29:50:421 (2136) SPTI: '\\.\Physicaldrive2': 'USB2.0 CF CardReader ': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 65536
06:29:50:421 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:437 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:437 (2136) func: <<< iScsiSptiDevice::open
06:29:50:437 (2136) func: >>> iScsiSptiDevice::close
06:29:50:437 (2136) func: <<< iScsiSptiDevice::close
06:29:50:437 (2136) Srv: A new SPTI device '\\.\Physicaldrive2' found.
06:29:50:437 (2136) func: >>> iScsiServer::addDevice
06:29:50:437 (2136) func: <<< iScsiServer::addDevice
06:29:50:437 (2136) func: >>> iScsiSptiDevice::open
06:29:50:437 (2136) func: >>> iScsiSptiDevice::probe
06:29:50:437 (2136) func: <<< iScsiSptiDevice::probe
06:29:50:437 (2136) SPTI: '\\.\Physicaldrive3': Cannot get SCSI address for the device: The request is not supported. (code: 50).
06:29:50:437 (2136) SPTI: '\\.\Physicaldrive3': 'USB2.0 CBO CardReader ': adapter 0, bus 0, target id 0, LUN 0; maxTransferLength 65536
06:29:50:437 (2136) func: >>> iScsiSptiDevice::getBurnerFlags
06:29:50:453 (2136) func: <<< iScsiSptiDevice::getBurnerFlags
06:29:50:453 (2136) func: <<< iScsiSptiDevice::open
06:29:50:453 (2136) func: >>> iScsiSptiDevice::close
06:29:50:453 (2136) func: <<< iScsiSptiDevice::close
06:29:50:453 (2136) Srv: A new SPTI device '\\.\Physicaldrive3' found.
06:29:50:453 (2136) func: >>> iScsiServer::addDevice
06:29:50:453 (2136) func: <<< iScsiServer::addDevice
ImageFile[858] ProcessVolumeLetters: Found volume '\\?\Volume{91832a15-e5a0-11d8-acb8-806d6172696f}\', mount point 'C:\'.
ImageFile[858] ProcessVolumeLetters: Found volume '\\?\Volume{98e3f043-e5a1-11d8-a832-806d6172696f}\', mount point 'D:\'.
ImageFile[858] ProcessVolumeLetters: Found volume '\\?\Volume{98e3f044-e5a1-11d8-a832-806d6172696f}\', mount point 'E:\'.
ImageFile[858] ProcessVolumeLetters: Found volume '\\?\Volume{98e3f042-e5a1-11d8-a832-806d6172696f}\', mount point 'F:\'.
ImageFile[858] ProcessVolumeLetters: Found volume '\\?\Volume{04f4ecbe-e749-11d8-a844-000c41e549e4}\', mount point 'G:\'.
ImageFile[858] *ERROR* List_RefreshVolumes: Cannot open the volume '\\.\G:'.
ImageFile[858] *List_RefreshVolumes: Adding device 'ImageFile0' for volume '\\.\F:'.
ImageFile[858] *List_RefreshVolumes: Adding device 'ImageFile1' for volume '\\.\E:'.
ImageFile[858] *List_RefreshVolumes: Adding device 'ImageFile2' for volume '\\.\D:'.
ImageFile[858] *ERROR* List_RefreshVolumes: Cannot open the volume '\\.\C:'.
06:29:50:656 (2136) func: >>> iScsiSscDevice::open
ImageFile[858] *SscPort_Create: ImageFile: opening device 'ImageFile2', image file '\\.\D:'.
ImageFile[858] *ERROR* ImageFile_Create: '\\.\D:': cannot get size of the image file (0x00000001).
06:29:50:765 (2136) SCSI: Failed to create 'ImageFile2' device.
06:29:50:765 (2136) func: <<< iScsiSscDevice::open
06:29:50:765 (2136) Srv: Test for device 'ImageFile2' failed.
06:29:50:765 (2136) func: >>> iScsiSscDevice::close
06:29:50:765 (2136) func: <<< iScsiSscDevice::close
06:29:50:765 (2136) func: >>> iScsiSscDevice::open
ImageFile[858] *SscPort_Create: ImageFile: opening device 'ImageFile1', image file '\\.\E:'.
ImageFile[858] *ERROR* ImageFile_Create: '\\.\E:': cannot get size of the image file (0x00000001).
06:29:50:875 (2136) SCSI: Failed to create 'ImageFile1' device.
06:29:50:875 (2136) func: <<< iScsiSscDevice::open
06:29:50:875 (2136) Srv: Test for device 'ImageFile1' failed.
06:29:50:875 (2136) func: >>> iScsiSscDevice::close
06:29:50:875 (2136) func: <<< iScsiSscDevice::close
06:29:50:875 (2136) func: >>> iScsiSscDevice::open
ImageFile[858] *SscPort_Create: ImageFile: opening device 'ImageFile0', image file '\\.\F:'.
ImageFile[858] *ERROR* ImageFile_Create: '\\.\F:': cannot get size of the image file (0x00000001).
06:29:50:875 (2136) SCSI: Failed to create 'ImageFile0' device.
06:29:50:875 (2136) func: <<< iScsiSscDevice::open
06:29:50:875 (2136) Srv: Test for device 'ImageFile0' failed.
06:29:50:875 (2136) func: >>> iScsiSscDevice::close
06:29:50:875 (2136) func: <<< iScsiSscDevice::close
06:29:50:875 (2136) func: <<< iScsiServer::refreshDeviceList
06:29:50:875 (2136) func: >>> iScsiServer::listenConnections
06:29:50:875 (2136) Srv: (FREE) Binding to 0.0.0.0:3260 ...
06:29:50:875 (2136) Srv: (FREE) Waiting for a connection at port 3260 ...
06:29:50:875 (2128) func: >>> TelnetListener::listenConnections
06:29:50:875 (2128) conf: Waiting for a control connection at port 3261 ...
06:30:22:484 (2132) ntsrv: Got SERVICE_CONTROL_STOP signal.
06:30:22:484 (2132) func: >>> iScsiServer::stop
06:30:22:484 (2132) func: <<< iScsiServer::stop
06:30:22:484 (2136) func: <<< iScsiServer::listenConnections
06:30:22:484 (2136) func: >>> TelnetListener::stop
06:30:22:484 (2128) conf: Stop listening to control connections.
06:30:22:484 (2128) func: <<< TelnetListener::listenConnections
06:30:22:484 (2136) func: <<< TelnetListener::stop
06:30:22:484 (2136) Srv: Timeout 10 second(s)...
06:30:22:484 (2136) Srv: Shutdown completed.
06:30:22:484 (2136) func: >>> iScsiSscDevice::close
06:30:22:484 (2136) func: <<< iScsiSscDevice::close
06:30:22:484 (2136) S: the device 'RamDrive0' is closed.
06:30:22:484 (2136) func: >>> iScsiSptiDevice::close
06:30:22:484 (2136) func: <<< iScsiSptiDevice::close
06:30:22:484 (2136) S: the device '\\.\Physicaldrive1' is closed.
06:30:22:484 (2136) func: >>> iScsiSscDevice::close
06:30:22:484 (2136) func: <<< iScsiSscDevice::close
06:30:22:484 (2136) func: >>> iScsiServer::stop
06:30:22:484 (2136) func: <<< iScsiServer::stop
User avatar
Alex (staff)
Staff
Posts: 177
Joined: Sat Jun 26, 2004 8:49 am

Fri Aug 06, 2004 7:42 am

Hi,

Actually StarWind (as any other socket application) knows nothing about ethernet frame size. It just uses BSD sockets interface. If large frames are the reason of the error it should be located in NIC or its driver.

I guess the reason why you see this error with StarWind only is that the rest of network activities operates with small amounts and data and so frame size does not exceeds 1514 for them. StarWind uses 64K transfers so each transfer will cause sending of large frame. Try to test large data transfers across this link.

BTW. 9K jumbo frames have 9014 not 9000 bytes. May be you NIC expects 9014 and wrongly interprets 9000?
Best regards,
Alexey.
Codiak6335

Fri Aug 06, 2004 8:03 am

I'll check the driver for some type of log.
I'll setup a test tomorrow and hammer it with larger packets without Stawind running and see what occurs.
Funny the 9000 vs 9014 though.... a gui shouldn't let the user enter invalid values... shame on Linksys ;)
User avatar
anton (staff)
Site Admin
Posts: 4008
Joined: Fri Jun 18, 2004 12:03 am
Location: British Virgin Islands
Contact:

Fri Aug 06, 2004 8:19 pm

Yup! Just give your hardware a hard times before we'll start fixing what's more then possibly not broken :)
Codiak6335 wrote:I'll check the driver for some type of log.
I'll setup a test tomorrow and hammer it with larger packets without Stawind running and see what occurs.
Funny the 9000 vs 9014 though.... a gui shouldn't let the user enter invalid values... shame on Linksys ;)
Regards,
Anton Kolomyeytsev

Chief Technology Officer & Chief Architect, StarWind Software

Image
Locked