Starwind Service Hangs

Tape drive and auto-loader redirector over iSCSI

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

Post Reply
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Fri Oct 12, 2012 11:12 am

Good day

I am having an issue with my starwind tape redirector. I installed it, worked perfectly for a couple of backups and since then it no longer works (last night). What happens it that it starts the backup, the server gets to a point then no longer writes to tape. herewith some details.

- I am using an HP 1/8 autoloader.
- I changed maxtransferlength
- installed all drivers on both servers (same version)
- updated firmware on device
- setup tape redirector with 2 targets (1 for autoloader, 1 for tape)
- setup iscsi initiator
- linked both devices
- scanned DPM to pickup devices
- did a device clean (with cleaning tape)

The issue I am experiencing is that the taperedirector.exe is hanging on the target computer, I have restarted and tried to connect when the management console asks me for a license key from time to time. It does accept the one I have (sometimes) and other times it it does not connect. The process itself also fails to quit with killtask as well as windows task manager

- I am using windows 2008 R2 on both servers.

On a good note - the few tape backups that completed successfully (1 was 360GB in an hour) impressive.. the autoloader changed tapes, everything was looking good.. then..?

Pls help.

thanks
User avatar
anton (staff)
Site Admin
Posts: 4008
Joined: Fri Jun 18, 2004 12:03 am
Location: British Virgin Islands
Contact:

Fri Oct 12, 2012 11:46 am

Please reproduce the issue and send us back some logs. Also please check system event log for error messages from tape drive controller (aborted commands, timeouts etc).
Regards,
Anton Kolomyeytsev

Chief Technology Officer & Chief Architect, StarWind Software

Image
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Mon Oct 15, 2012 12:22 pm

Thanks, I see the following occurs in the log files when it hangs.

(initiator)

10/15 14:11:00.430 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:00.830 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:01.231 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:01.631 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:02.031 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:02.431 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:02.831 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:03.231 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:03.631 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:04.031 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:04.431 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:04.831 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:05.231 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:05.632 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:05.926 Found language dll: language id: 0x0409 (English (United States)).
10/15 14:11:06.032 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:06.432 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:06.832 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:07.232 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:07.632 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:08.032 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:08.432 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:08.832 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:09.232 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:09.632 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:10.032 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2
10/15 14:11:10.432 CMainFrame::PoolingServiceEvents: Event checking failed, status == 2


and target device is

10/15 13:33:04.183 7d4 Params: <<< String param 'InitiatorName': received 'iqn.2008-08.com.starwindsoftware:server03.domain-autoloader:server02', accepted 'iqn.2008-08.com.starwindsoftware:c
dbhodpm03.domain-autoloader:server02'
10/15 13:33:04.183 7d4 Params: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:server03.domain-tapedevice', accepted 'iqn.2008-08.com.starwindsoftware:server03.domain
int-tapedevice'
10/15 13:33:04.183 7d4 Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
10/15 13:33:04.183 7d4 Params: <<< Enum param 'AuthMethod': received 'None', accepted 'None'
10/15 13:33:04.183 7d4 SPTI: '\\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#6&13fd438&0&000400#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}': share: 3 ('rw').
10/15 13:33:04.183 7d4 SPTI: '\\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi#6&13fd438&0&000400#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}': 'HP Ultrium 4-SCSI W61W': adapter 5, bus 0, target 4,
LUN 0; maxTransferLength 16777215, alignmentMask 0x0
10/15 13:33:04.183 7d4 Tgt: open 'iqn.2008-08.com.starwindsoftware:server03.domain-tapedevice': 1 session(s) opened, 65535 more allowed.
10/15 13:33:04.183 7d4 Params: <<< Enum param 'AuthMethod': received 'None', accepted 'None'
10/15 13:33:04.183 7d4 Params: >>> AuthMethod=None.
10/15 13:33:04.183 7d4 Params: >>> TargetAlias=TapeDevice.
10/15 13:33:04.183 7d4 Params: >>> TargetPortalGroupTag=1.
10/15 13:33:04.183 69c T[2,1]: session 0x2, connection 0x2 : end of stage 0, next stage 1.
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'MaxConnections': received 1, accepted 1
10/15 13:33:04.183 7d4 Params: <<< Enum param 'HeaderDigest': received 'None', accepted 'None'
10/15 13:33:04.183 7d4 Params: <<< Enum param 'DataDigest': received 'None', accepted 'None'
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'OFMarker': received No, accepted 0
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'IFMarker': received No, accepted 0
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'InitialR2T': received No, accepted 0
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'ImmediateData': received Yes, accepted 1
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 65536, accepted 65536
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'FirstBurstLength': received 65536, accepted 65536
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'DefaultTime2Wait': received 5, accepted 5
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'DefaultTime2Retain': received 20, accepted 20
10/15 13:33:04.183 7d4 Params: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
10/15 13:33:04.183 7d4 Params: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
10/15 13:33:04.183 7d4 Params: >>> ErrorRecoveryLevel=0.
10/15 13:33:04.183 7d4 Params: >>> MaxConnections=1.
10/15 13:33:04.183 7d4 Params: >>> HeaderDigest=None.
10/15 13:33:04.183 7d4 Params: >>> DataDigest=None.
10/15 13:33:04.183 7d4 Params: >>> OFMarker=No.
10/15 13:33:04.183 7d4 Params: >>> IFMarker=No.
10/15 13:33:04.183 7d4 Params: >>> InitialR2T=No.
10/15 13:33:04.183 7d4 Params: >>> ImmediateData=Yes.
10/15 13:33:04.183 7d4 Params: >>> MaxRecvDataSegmentLength=262144.
10/15 13:33:04.183 7d4 Params: >>> MaxBurstLength=262144.
10/15 13:33:04.183 7d4 Params: >>> FirstBurstLength=65536.
10/15 13:33:04.183 7d4 Params: >>> DefaultTime2Wait=5.
10/15 13:33:04.183 7d4 Params: >>> DefaultTime2Retain=20.
10/15 13:33:04.183 7d4 Params: >>> MaxOutstandingR2T=1.
10/15 13:33:04.183 7d4 Params: >>> DataPDUInOrder=Yes.
10/15 13:33:04.183 7d4 Params: >>> DataSequenceInOrder=Yes.
10/15 13:33:04.183 69c T[2,1]: session 0x2, connection 0x2 : end of stage 1, next stage 3.
10/15 13:33:04.183 69c C[2], IN_LOGIN: Event - LOGIN_ACCEPT.
10/15 13:33:04.183 69c C[2], LIN: T5.
10/15 13:33:10.906 498 conf: Accepted control connection from 127.0.0.1:52232.
User avatar
anton (staff)
Site Admin
Posts: 4008
Joined: Fri Jun 18, 2004 12:03 am
Location: British Virgin Islands
Contact:

Mon Oct 15, 2012 1:34 pm

Nice. Start with replacing StarWind initiator with MS initiator. We don't support anything expcet MS in production.
If you'd continue to see the same issues please send target side logs ZIPPED to support@starwindsoftware.com so we could take a look. Thanks!
Regards,
Anton Kolomyeytsev

Chief Technology Officer & Chief Architect, StarWind Software

Image
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Mon Oct 15, 2012 4:05 pm

Logs sent as requested.

Further action taken, uninstalled antivirus - still no change.

thanks
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Mon Oct 15, 2012 4:08 pm

Just to clarify.

- I uninstalled starwind initiator
- installed MS initiator
- configured to point to targets
- uninstalled AV from server
- checked windows logs, no issues found
- sent starwind logs from the target
User avatar
anton (staff)
Site Admin
Posts: 4008
Joined: Fri Jun 18, 2004 12:03 am
Location: British Virgin Islands
Contact:

Mon Oct 15, 2012 8:36 pm

So does it work as expected now? Or do you still have issues (and send us corresponding logs)? Just to clarify :)
gynts@cidb.org.za wrote:Just to clarify.

- I uninstalled starwind initiator
- installed MS initiator
- configured to point to targets
- uninstalled AV from server
- checked windows logs, no issues found
- sent starwind logs from the target
Regards,
Anton Kolomyeytsev

Chief Technology Officer & Chief Architect, StarWind Software

Image
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Tue Oct 16, 2012 7:07 am

It still does not work and I did send to the email address provided.

thanks
User avatar
Anatoly (staff)
Staff
Posts: 1675
Joined: Tue Mar 01, 2011 8:28 am
Contact:

Tue Oct 16, 2012 9:33 am

We have received the logs, thank you.
For some reason we do not see any SPTI-related errors.
May I ask you to try to reproduce the issue, after that go to the C:\Program Files\StarWind Software\StarWind\logs and send us the two latest log files. Probably I will ask you to upload them to some file share and provide us with the download link (we need this to avoid mailbox filter related issues).
Best regards,
Anatoly Vilchinsky
Global Engineering and Support Manager
www.starwind.com
av@starwind.com
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Tue Oct 16, 2012 11:00 am

ok, so I have made some progress.
I increased the buffersize on the NIC's and all was going ok.. for a few backups. now another error is occurring. (hope this makes sense)

I am getting the following from initiator: (if I restart, the server does some backups then this occurs)
- Initiator failed to connect to the target. Target IP address and TCP Port number are given in dump data.

I am getting the following issues on target machine : taperedirector (this occurs after a popup of "connection to host lost")
in windows logs
"The following boot-start or system-start driver(s) failed to load: StarISCSI"

in starwind logs
10/16 11:10:02.775 848 C[4], FREE: Event - CONNECTED.
10/16 11:10:02.775 848 C[4], XPT_UP: T3.
10/16 11:10:02.775 a9c C[4], XPT_UP: Login request: ISID 0x400001370001, TSIH 0x0000.
10/16 11:10:02.775 a9c C[4], XPT_UP: Event - LOGIN.
10/16 11:10:02.775 a9c C[4], IN_LOGIN: T4.
10/16 11:10:02.775 a9c Params: <<< String param 'InitiatorName': received 'iqn.1991-05.com.microsoft:server02.domain', accepted 'iqn.1991-05.com.microsoft:server02.domain'
10/16 11:10:02.775 a9c Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
10/16 11:10:02.775 a9c Params: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:server03.domain-tapedevice', accepted 'iqn.2008-08.com.starwindsoftware:server03.domain-tapedevice'
10/16 11:10:02.775 a9c Params: <<< Enum param 'AuthMethod': received 'None', accepted 'None'
10/16 11:10:02.775 a9c T[4,1]: An old session <2> from the same Initiator/ISID found. Session reinstatement starting...
10/16 11:10:02.775 a9c C[2], LIN: Close socket.
10/16 11:10:02.775 a9c S[2]: Connection <2> stat (1)
10/16 11:10:03.276 a9c T[4,1]: Waiting for the old session <2> to shut down...
10/16 11:10:03.276 a9c T[4,1]: Old session <2> is still present. Force clean up...
10/16 11:11:16.769 a4c T[1,39]: iqn.2008-08.com.starwindsoftware:server03.domain-autoloader: Management command: LUN 0x0 RESET.
10/16 11:11:16.769 a4c Tgt: iqn.2008-08.com.starwindsoftware:server03.domain-autoloader Resetting LUN 0 (Device \\?\scsi#changer&ven_hp&prod_1x8_g2_autoldr#6&13fd438&0&000401#{53f56310-b6bf-11d0-94f2-00a0c91efb8b} LUN 0)...
10/16 11:11:16.769 a4c PR: Set Unit attention 0x29/0x3 for session 0x1 from iqn.1991-05.com.microsoft:server02.domain,400001370001.
10/16 11:11:16.769 a4c C[1], LIN: recvData returned 10054
10/16 11:11:16.769 a4c C[1], LIN: *** 'recv' thread: recv failed 10058.
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Tue Oct 16, 2012 11:07 am

also getting this on the target machine.

Application popup: Windows - Delayed Write Failed : Exception Processing Message 0xc000a082 Parameters 0x000007FEFD97718C 0x000007FEFD97718C 0x000007FEFD97718C 0x000007FEFD97718C
User avatar
Anatoly (staff)
Staff
Posts: 1675
Joined: Tue Mar 01, 2011 8:28 am
Contact:

Tue Oct 16, 2012 11:46 am

Dear Sir,

Had you any chance to do what I have previously requested?

I will provide you with the quotation below:
May I ask you to try to reproduce the issue, after that go to the C:\Program Files\StarWind Software\StarWind\logs and send us the two latest log files. Probably I will ask you to upload them to some file share and provide us with the download link (we need this to avoid mailbox filter related issues).
Best regards,
Anatoly Vilchinsky
Global Engineering and Support Manager
www.starwind.com
av@starwind.com
gynts@cidb.org.za
Posts: 8
Joined: Fri Oct 12, 2012 10:58 am

Tue Oct 16, 2012 2:57 pm

Afternoon.

I did not, due to; the errors I am getting now are different and posted them onto the forum. pls advise if you still need them. I think the errors now (as explained above) are perhaps solvable without them. I do not have access to a FTP / Web server I can put the log onto.
User avatar
Anatoly (staff)
Staff
Posts: 1675
Joined: Tue Mar 01, 2011 8:28 am
Contact:

Tue Oct 16, 2012 3:13 pm

Yes, we still need them. You can upload your logs on any file hosting kind of Mediafire.
Best regards,
Anatoly Vilchinsky
Global Engineering and Support Manager
www.starwind.com
av@starwind.com
Post Reply