Page 1 of 1

Starwind iSCSI Initiator

Posted: Mon May 13, 2013 10:33 pm
by ryanw
Hi All,

Been having the following problems for the last couple days,and this one has stumped me.

I have done the following.

1. Installed the Free version of the iSCSI San on Server X and have created the virtual disk as required. no problems there.
2. Installed the iSCSI Initiator from Starwind, open and went to connect to remote device, no luck. Come's up with an error that the firewall may be blocking the connection/Server is refusing connections.. I have checked and the firewall is off on Server X, and Starwind is in the allowed programs list.

5/14 7:52:05.031 22cc VTAPE: *** TapeEmulCtrlApiStart: StarWind VTL License Type is 3
5/14 7:52:05.031 22cc VTAPE: *** TapeEmulCtrlApiStart: This Enterprise Edition supports a maximum of 64 devices, each up to 2097152 MB in length.
5/14 7:52:05.031 22cc conf: 'VirtualTape.dll' loaded successfully.
5/14 7:52:05.032 22cc HA: *SscPort_InitEx: Unused parameter: 'module'
5/14 7:52:05.032 22cc HA: *SscPort_InitEx: Unused parameter: 'type'
5/14 7:52:05.032 22cc Sw -> Browser_InitDirInfo: >>
5/14 7:52:05.032 22cc Sw: Browser_InitDirInfo: Parse ImageDir: '*|cmdfv|My Computer|img'
5/14 7:52:05.032 22cc Sw: *Browser_InitDirInfo:
Dirname: '*'
Rights: 0x1f
Alias: 'My Computer'
Extensions: 'img'
5/14 7:52:05.032 22cc Sw <- Browser_InitDirInfo: return (0x1)
5/14 7:52:05.032 22cc Sw -> Browser_InitDirInfo: >>
5/14 7:52:05.032 22cc Sw: Browser_InitDirInfo: Parse ImageDir: '*|cdmfv|Headers|swdsk'
5/14 7:52:05.032 22cc Sw: *Browser_InitDirInfo:
Dirname: '*'
Rights: 0x1f
Alias: 'Headers'
Extensions: 'swdsk'
5/14 7:52:05.032 22cc Sw <- Browser_InitDirInfo: return (0x1)
5/14 7:52:05.032 22cc Sw -> Browser_InitDirInfo: >>
5/14 7:52:05.032 22cc Sw: Browser_InitDirInfo: Parse ImageDir: 'Device Headers|cdmfv|DefaultHeaderPath|swdsk'
5/14 7:52:05.032 22cc Sw: *Browser_InitDirInfo:
Dirname: 'C:\Program Files\StarWind Software\StarWind\Device Headers'
Rights: 0x1f
Alias: 'DefaultHeaderPath'
Extensions: 'swdsk'
5/14 7:52:05.032 22cc Sw <- Browser_InitDirInfo: return (0x1)
5/14 7:52:05.032 22cc HA: SscPort_InitEx: OS major version more then 5, then will be used internal transport.5/14 7:52:05.032 22cc HA: SscPort_InitEx: (build 20130329, built Mar 29 2013 19:13:22)
VendorId = ' '
ProductId = ' '
Revision = '0001'
DefImageDir = '*\'
Volumes = 0
ExeDir = 'C:\Program Files\StarWind Software\StarWind\'
5/14 7:52:05.032 22cc HA: CHADevice::InitializeModule: Params(p_hCxxLogger = 0x000000000145B800, p_lDbgLevel = 1, p_pCallback = 0x00000000013C55F8, p_hPluginHandle = 0x0000000002533710, p_ScsiTransportType = 3) ENTERed
5/14 7:52:05.033 22cc conf: 'HAImage.dll' loaded successfully.
5/14 7:52:05.034 22cc conf: Reaction of type 'eventlog' [0xFFFFFFFF, 0x0C] loaded successfully.
5/14 7:52:05.034 22cc conf: Variable 'DefaultAccessPolicy' is set to 'allow'.
5/14 7:52:05.034 22cc Srv: Update tracker options: UpdatePeriod = 7, UpdateLastRequest = 20100101, UpdateHost = www.starwindsoftware.com, UpdatePage = /updatetracker/index.php, UpdatePort = 80, UpdateCopyId =
5/14 7:52:05.035 22cc Srv: Refreshing device list (complete)...
5/14 7:52:05.045 22cc SPTI: '\\?\scsi#disk&ven_hp&prod_logical_volume#5&334e8424&0&000400#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}': 'HP LOGICAL VOLUME 5.70': adapter 5, bus 0, target 4, LUN 0; maxTransferLength 524288, alignmentMask 0x3
5/14 7:52:05.045 22cc PerformanceDB: CPerformanceCounter::WriteOperationalData called on uninitialized counter(DB entry: 0000000000000000, Record: 0000000000000000).
5/14 7:52:05.045 22cc PerformanceDB: CPerformanceCounter::Close exiting with error: WriteOperationalData failed.
5/14 7:52:05.045 22cc SPTI: '\\?\scsi#disk&ven_hp&prod_logical_volume#5&334e8424&0&000500#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}': 'HP LOGICAL VOLUME 5.70': adapter 5, bus 0, target 5, LUN 0; maxTransferLength 524288, alignmentMask 0x3
5/14 7:52:05.045 22cc PerformanceDB: CPerformanceCounter::WriteOperationalData called on uninitialized counter(DB entry: 0000000000000000, Record: 0000000000000000).
5/14 7:52:05.045 22cc PerformanceDB: CPerformanceCounter::Close exiting with error: WriteOperationalData failed.
5/14 7:52:05.048 22cc SPTI: '\\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&1a9eeae2&0&070000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}': 'IBM ULTRIUM-HH4 97F1': adapter 4, bus 7, target 0, LUN 0; maxTransferLength 131072, alignmentMask 0x3
5/14 7:52:05.048 22cc Srv: Found SPTI device '\\?\scsi#sequential&ven_ibm&prod_ultrium-hh4#5&1a9eeae2&0&070000#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}': 'IBM ULTRIUM-HH4 97F1'
5/14 7:52:05.050 38d4 conf: Waiting for Control connections at 0.0.0.0:3261 ...
5/14 7:52:05.050 4eb8 bc: Waiting for broadcast UDP packets at 0.0.0.0:3261...
5/14 7:52:05.052 22cc Srv: bind() to 192.168.22.207:3260 failed: Only one usage of each socket address (protocol/network address/port) is normally permitted. (code: 10048).
5/14 7:52:05.052 22cc error: assertion failed: c:\_starwind\_release_60\starwind\service\common\fn_common.cpp:28 (isEmpty())
5/14 7:52:05.052 22cc Srv: Waiting for iSCSI connections at 127.0.0.1:3260 ...
5/14 7:52:14.798 38d4 conf: Accepted control connection from 127.0.0.1:64274.
5/14 7:52:46.487 49dc Srv: StarWindService::UpdateTrackerThread: SW_CheckUpdate(host: 'www.starwindsoftware.com', page: '/updatetracker/index.php'') failed, error code 31(0x1f)!
5/14 7:59:27.596 2b64 FileBrowser: Return param: 'FileSize' = 'Failed: invalid path provided'
5/14 7:59:31.436 2b64 FileBrowser: Return param: 'FileSize' = 'Failed: invalid path provided'
5/14 7:59:31.446 2b64 FileBrowser: Return param: 'FileSize' = 'Failed: invalid path provided'
5/14 7:59:31.489 2b64 IMG: ImageFile_CreateRawFile: File 'D:\Email Archive\Email Archive.img', size: 102400 MB, flags 0x240...
5/14 7:59:32.079 2b64 IMG: *** ImageFile_CreateRawFile: SetEndOfFile() failed. Status (0) !
5/14 7:59:32.079 2b64 IMG: ImageFile_CreateRawFile: Zero out only the first and the last 1MB of the image.
5/14 7:59:32.079 2b64 IMG: ImageFile_CreateRawFile: WARNING: This can damage security if the file image is exported directly to untrusted clients!
5/14 7:59:32.105 2b64 IMG: ImageFile_CreateRawFile: Progress: 99.9% (102399 MB, elapsed 0 sec, remain ~0 sec)...
5/14 7:59:32.398 2b64 IMG: ImageFile_CreateRawFile: File 'D:\Email Archive\Email Archive.img' created. Total elapsed time = 0 sec.
5/14 8:00:18.547 2b64 FileBrowser: Return param: 'FileSize' = '107374182400'
5/14 8:00:18.726 2b64 FileBrowser: Return param: 'FileSize' = '107374182400'
5/14 8:00:18.733 2b64 FileBrowser: Return param: 'FileSize' = '107374182400'
5/14 8:02:16.125 2b64 Tgt: : parameter 'file', value 'My Computer\D\Email Archive\Email Archive.img'.
5/14 8:02:16.125 2b64 Tgt: : parameter 'asyncmode', value 'yes'.
5/14 8:02:16.125 2b64 Tgt: : parameter 'CacheMode', value 'wb'.
5/14 8:02:16.125 2b64 Tgt: : parameter 'CacheSizeMB', value '128'.
5/14 8:02:16.125 2b64 IMG: SscPort_Create: Opening device 'ImageFile1', image file 'My Computer\D\Email Archive\Email Archive.img', buffering=0, async=1, readonly=0.
5/14 8:02:16.168 2b64 IMG: ImageFile_Create: 'D:\Email Archive\Email Archive.img': type 0, geometry: sct 16, trks 32, cyl 409600, TotalSectors: 209715200
5/14 8:02:16.168 2b64 Ssc: *** SscScsi_GetVolumeSectorSize: '\\.\D:' IOCTL_STORAGE_QUERY_PROPERTY(StorageAccessAlignmentProperty) failed (error 50)
5/14 8:02:16.168 2b64 IMG: ImageFile_Create: VendorId 'ROCKET ', ProductId 'IMAGEFILE ', Revision '0001', Serial '22C966761DA88462'
5/14 8:02:16.169 2b64 CACHE: *** SWCache_Create: Cache parameters: Mode = 1, Flags = 0, Size = 128 MB, SectorSize = 512, BlockExpiryPeriod = 0, DiskSizeInSectors = 209715200
5/14 8:02:16.200 2b64 SCSI: EUI64 retrieved: 6284A81D7666C922 (hex)
5/14 8:02:16.200 2b64 SCSI: SerialID retrieved: 22C966761DA8846
5/14 8:02:16.200 2b64 conf: Device [0x0000000002566890] 'ImageFile1' has been created.
5/14 8:02:16.212 2b64 Srv: Creating target 'iqn.2008-08.com.starwindsoftware:-emailarchive', device list 'ImageFile1'...
5/14 8:02:16.213 2b64 Tgt: : parameter 'header', value '0'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'file', value 'My Computer\D\Email Archive\Email Archive.img'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'buffering', value 'no'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'asyncmode', value 'yes'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'ImageSizeLow', value '0'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'ImageSizeHigh', value '25'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'readonly', value 'no'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'readonly', value 'no'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'DeviceState', value '1'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'CacheMode', value 'wb'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'CacheSizeMB', value '128'.
5/14 8:02:16.213 2b64 Tgt: : parameter 'CacheBlockExpiryPeriodMS', value '5000'.
5/14 8:02:16.213 2b64 Tgt: : parameter '#_TargetName_#', value 'iqn.2008-08.com.starwindsoftware:-emailarchive'.
5/14 8:02:16.213 2b64 Tgt: iqn.2008-08.com.starwindsoftware:-emailarchive: device ImageFile1: new LUN 0 mapped to target LUN 0.
5/14 8:02:16.213 2b64 Tgt: iqn.2008-08.com.starwindsoftware:-emailarchive: attached device ImageFile1 (LUNs found: 1).
5/14 8:02:16.213 2b64 conf: Target [0x0000000002599670] 'iqn.2008-08.com.starwindsoftware:-emailarchive' has been created, 1 devices attached.
5/14 8:05:40.133 38d4 conf: Accepted control connection from 192.168.22.206:4171.
5/14 8:05:50.121 47ac conf: Control connection closed.
5/14 8:15:15.199 38d4 conf: Accepted control connection from 192.168.22.206:44106.
5/14 8:15:25.186 53e4 conf: Control connection closed.
5/14 8:16:23.219 38d4 conf: Accepted control connection from 192.168.22.206:44156.
5/14 8:16:33.208 5350 conf: Control connection closed.
5/14 8:18:57.515 38d4 conf: Accepted control connection from 192.168.22.206:44261.
5/14 8:19:07.513 5368 conf: Control connection closed.
5/14 8:19:14.643 38d4 conf: Accepted control connection from 192.168.22.207:64668.
5/14 8:19:14.644 3ec0 conf: Control connection closed.
5/14 8:19:16.467 38d4 conf: Accepted control connection from 192.168.22.207:64669.
5/14 8:21:55.492 38d4 conf: Accepted control connection from 192.168.22.206:44432.
5/14 8:22:05.485 2f64 conf: Control connection closed.
5/14 8:25:05.422 38d4 conf: Accepted control connection from 192.168.22.206:44632.
5/14 8:25:15.422 52fc conf: Control connection closed.
5/14 8:27:44.063 38d4 conf: Accepted control connection from 192.168.22.206:44786.
5/14 8:27:54.035 5134 conf: Control connection closed.
5/14 8:29:55.369 38d4 conf: Accepted control connection from 192.168.22.206:16614.
5/14 8:30:05.354 5128 conf: Control connection closed.
5/14 8:31:37.446 38d4 conf: Accepted control connection from 192.168.22.206:16698.
5/14 8:31:47.435 4e60 conf: Control connection closed.
5/14 8:33:11.278 5384 conf: Variable 'listen' is set to '*,'.
5/14 8:33:11.365 22cc Srv: Restarting listening...
5/14 8:33:11.367 22cc Srv: bind() to 192.168.22.207:3260 failed: Only one usage of each socket address (protocol/network address/port) is normally permitted. (code: 10048).
5/14 8:33:11.367 22cc error: assertion failed: c:\_starwind\_release_60\starwind\service\common\fn_common.cpp:28 (isEmpty())
5/14 8:33:11.367 22cc Srv: Waiting for iSCSI connections at 127.0.0.1:3260 ...
5/14 8:33:22.133 5384 conf: Variable 'nolisten' is set to '127.0.0.1:3260'.
5/14 8:33:22.169 22cc Srv: Restarting listening...
5/14 8:33:22.171 22cc Srv: bind() to 192.168.22.207:3260 failed: Only one usage of each socket address (protocol/network address/port) is normally permitted. (code: 10048).
5/14 8:33:22.171 22cc error: assertion failed: c:\_starwind\_release_60\starwind\service\common\fn_common.cpp:28 (isEmpty())
5/14 8:33:22.171 22cc Srv: No iSCSI ports to listen to. Idle wait...
5/14 8:33:38.071 5384 conf: Variable 'listen' is set to '*,'.
5/14 8:34:24.848 5384 conf: Variable 'nolisten' is set to ''.
5/14 8:34:24.850 22cc Srv: Restarting listening...
5/14 8:34:24.852 22cc Srv: bind() to 192.168.22.207:3260 failed: Only one usage of each socket address (protocol/network address/port) is normally permitted. (code: 10048).
5/14 8:34:24.852 22cc error: assertion failed: c:\_starwind\_release_60\starwind\service\common\fn_common.cpp:28 (isEmpty())
5/14 8:34:24.852 22cc Srv: Waiting for iSCSI connections at 127.0.0.1:3260 ...
5/14 8:38:38.597 38d4 conf: Accepted control connection from 192.168.22.206:17181.
5/14 8:38:48.588 469c conf: Control connection closed.
5/14 8:39:23.056 2b64 conf: Control connection closed.
5/14 8:39:23.056 5384 conf: Control connection closed.
5/14 8:44:18.385 38d4 conf: Accepted control connection from 127.0.0.1:65051.
5/14 8:44:23.823 38d4 conf: Accepted control connection from 192.168.22.207:65053.
5/14 8:44:56.794 38d4 conf: Accepted control connection from 192.168.22.206:8900.
5/14 8:45:06.793 52d8 conf: Control connection closed.
5/14 8:46:05.251 4af0 conf: Control connection closed.
5/14 8:46:05.251 4c88 conf: Control connection closed.
5/14 8:52:25.683 38d4 conf: Accepted control connection from 192.168.22.206:9224.
5/14 8:52:35.681 2d90 conf: Control connection closed.
5/14 8:53:17.696 38d4 conf: Accepted control connection from 192.168.22.206:9295.
5/14 8:53:27.683 4c9c conf: Control connection closed.
5/14 8:54:35.326 38d4 conf: Accepted control connection from 127.0.0.1:65224.
5/14 8:54:40.355 38d4 conf: Accepted control connection from 192.168.22.207:65225.
5/14 8:54:54.036 38d4 conf: Accepted control connection from 192.168.22.206:9399.
5/14 8:55:04.037 56d8 conf: Control connection closed.
5/14 8:56:32.105 5678 conf: Control connection closed.
5/14 8:56:36.136 5650 conf: Control connection closed.
5/14 8:57:00.006 38d4 conf: Accepted control connection from 192.168.22.207:65251.
5/14 8:57:00.007 46fc conf: Control connection closed.
5/14 8:57:01.069 38d4 conf: Accepted control connection from 192.168.22.207:65253.
5/14 8:58:04.795 38d4 conf: Accepted control connection from 192.168.22.206:9547.
5/14 8:58:14.773 38f4 conf: Control connection closed.
5/14 9:06:39.105 38d4 conf: Accepted control connection from 192.168.22.206:53166.
5/14 9:06:49.104 5494 conf: Control connection closed.
5/14 9:15:57.650 38d4 conf: Accepted control connection from 192.168.22.207:49208.
5/14 9:16:01.674 5b88 conf: Control connection closed.
5/14 9:16:06.919 38d4 conf: Accepted control connection from 192.168.22.206:61058.
5/14 9:16:16.918 5bb4 conf: Control connection closed.
5/14 9:20:26.929 38d4 conf: Accepted control connection from 192.168.22.206:61335.
5/14 9:23:02.554 38d4 conf: Accepted control connection from 192.168.22.206:61456.
5/14 9:23:12.536 5660 conf: Control connection closed.
5/14 9:26:23.634 56b8 conf: Acl record 'Test' loaded successfully.
5/14 9:26:42.614 38d4 conf: Accepted control connection from 192.168.22.206:61626.
5/14 9:26:52.613 4bdc conf: Control connection closed.
5/14 9:37:26.239 38d4 conf: Accepted control connection from 192.168.22.206:29731.
5/14 9:37:45.006 2ad0 conf: Control connection closed.
5/14 9:38:26.503 56b8 conf: Variable 'CtlInterface' is set to '192.168.22.207'.
5/14 9:38:39.643 38d4 conf: Accepted control connection from 192.168.22.207:49559.
5/14 9:38:48.980 38d4 conf: Accepted control connection from 192.168.22.206:29819.
5/14 9:38:52.562 2944 conf: Control connection closed.
5/14 9:38:58.979 5730 conf: Control connection closed.

Re: Starwind iSCSI Initiator

Posted: Tue May 14, 2013 4:16 pm
by Anatoly (staff)
1.What device type are you using?
2.Are there any firewalls that are blocking 3260 port?
3.Is there any AV software that may affect the system?
4.Have you tried MS iSCSI initiator?
5.Can you provide us with the detailed network diagram of your system?


Thank you