Unable to mount after unclean shutdown

gnomesenpai · Tue Nov 20, 2018 1:36 am

Hey guys, so had to reboot my one and only HA node thats left, and it spent over 30 minutes trying to stop the service and eventually gave up waiting for it. Since rebooting it's been 4 hours and the volume hasnt remounted and theirs 0 disk usage and the Starwind service is using between 15-18% cpu load, how can i fix this? I've got the free version so no console access which is annoying. Snipped of error logs below.

Code: Select all

1/20 1:18:39.089 1588 General: *** DDDisk_DispatchLimited: Got command 0x00 when device state is not DD_DISK_CREATION_COMPLETE! Current state is 2.
11/20 1:18:39.089 1588 Common: CStarWindStorageDevice::SendTestUnitReadyCommand: ForwardSscCommand() return not successfull SCSI status 2!
11/20 1:18:39.308 2e4 C[da0], IN_LOGIN: iScsiConnection::receive: recvData returned 10058 (0x274a)!
11/20 1:18:39.308 11c8 S[da0]: iScsiSession::~iScsiSession: ~Session
11/20 1:18:39.340 1448 General: *** DDDisk_DispatchLimited: Got command 0x00 when device state is not DD_DISK_CREATION_COMPLETE! Current state is 2.
11/20 1:18:39.340 1448 Common: CStarWindStorageDevice::SendTestUnitReadyCommand: ForwardSscCommand() return not successfull SCSI status 2!
11/20 1:18:40.089 1588 General: *** DDDisk_DispatchLimited: Got command 0x00 when device state is not DD_DISK_CREATION_COMPLETE! Current state is 2.
11/20 1:18:40.089 1588 Common: CStarWindStorageDevice::SendTestUnitReadyCommand: ForwardSscCommand() return not successfull SCSI status 2!
11/20 1:18:41.105 1588 General: *** DDDisk_DispatchLimited: Got command 0x00 when device state is not DD_DISK_CREATION_COMPLETE! Current state is 2.
11/20 1:18:41.105 1588 Common: CStarWindStorageDevice::SendTestUnitReadyCommand: ForwardSscCommand() return not successfull SCSI status 2!
11/20 1:18:41.465 a34 Common: *** MountTarget: (session(000001E0835BEC90), local(0.0.0.0), peer(192.168.2.119), port(3260), target(iqn.2008-08.com.starwindsoftware:10.20.0.4-scsi).
11/20 1:18:41.465 afc Common: *** MountTarget: (session(000001E0835CAF00), local(0.0.0.0), peer(10.20.0.4), port(3260), target(iqn.2008-08.com.starwindsoftware:10.20.0.4-scsi).
11/20 1:18:41.465 404 Common: *** MountTarget: (session(000001E0835BEA40), local(0.0.0.0), peer(10.20.0.5), port(3260), target(iqn.2008-08.com.starwindsoftware:10.20.0.4-scsi).
11/20 1:18:41.840 e18 Srv: iScsiServer::listenConnections: Accepted iSCSI connection from 10.20.0.11:45935 to 10.20.0.2:3260. (Id = 0xda1)
11/20 1:18:41.840 e18 S[da1]: iScsiSession::iScsiSession: Session (000001E0835AF080)
11/20 1:18:41.840 e18 C[da1], FREE: iScsiConnection::doTransition: Event - CONNECTED.
11/20 1:18:41.840 e18 C[da1], XPT_UP: iScsiConnection::fsmT3: T3.
11/20 1:18:42.090 7f0 C[da1], XPT_UP: iScsiConnection::handleFirstLogin: Login request: ISID 0x00023d000002, TSIH 0x0000.
11/20 1:18:42.090 7f0 C[da1], XPT_UP: iScsiConnection::doTransition: Event - LOGIN.
11/20 1:18:42.090 7f0 C[da1], IN_LOGIN: iScsiConnection::fsmT4: T4.
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< String param 'InitiatorName': received 'iqn.1998-01.com.vmware:5b01f7ae-a8bc-4b21-832d-e41f13e569b0-7a51138e', accepted 'iqn.1998-01.com.vmware:5b01f7ae-a8bc-4b21-832d-e41f13e569b0-7a51138e'
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:starwind-node-1-scsi', accepted 'iqn.2008-08.com.starwindsoftware:starwind-node-1-scsi'
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Enum param 'HeaderDigest': received 'None', accepted 'None'
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Enum param 'DataDigest': received 'None', accepted 'None'
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'IFMarker': received No, accepted 0
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'OFMarker': received No, accepted 0
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'InitialR2T': received No, accepted 0
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'ImmediateData': received Yes, accepted 1
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'FirstBurstLength': received 262144, accepted 262144
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'MaxConnections': received 1, accepted 1
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
11/20 1:18:42.090 7f0 Params: iScsiParameter::update: <<< Numeric param 'MaxRecvDataSegmentLength': received 131072, accepted 131072
11/20 1:18:42.090 7f0 HA: CHADevice::register_session: Client initiator iqn.1998-01.com.vmware:5b01f7ae-a8bc-4b21-832d-e41f13e569b0-7a51138e is trying to register a session within the 'iqn.2008-08.com.starwindsoftware:starwind-node-1-scsi' target... (sessId = 0xda1, initiatorNameIsid = iqn.1998-01.com.vmware:5b01f7ae-a8bc-4b21-832d-e41f13e569b0-7a51138e,00023D000002)
11/20 1:18:42.090 7f0 HA: CHADevice::register_session: Unable to register the new client session. The node is not active!
11/20 1:18:42.090 7f0 HA: CHADevice::register_session: Return code 21.
11/20 1:18:42.090 7f0 Tgt: *** iScsiTarget::openSession: iqn.2008-08.com.starwindsoftware:starwind-node-1-scsi: can't register session. The device 'HAImage1' is not ready.
11/20 1:18:42.090 7f0 T[da1,1]: ***iScsiTask::startLoginPhase: *ERROR* Login request: device open failed.
11/20 1:18:42.090 ea8 C[da1], IN_LOGIN: iScsiConnection::doTransition: Event - LOGIN_REJECT.
11/20 1:18:42.090 ea8 C[da1], IN_LOGIN: iScsiConnection::fsmT7: T7.
11/20 1:18:42.105 1588 General: *** DDDisk_DispatchLimited: Got command 0x00 when device state is not DD_DISK_CREATION_COMPLETE! Current state is 2.
11/20 1:18:42.105 1588 Common: CStarWindStorageDevice::SendTestUnitReadyCommand: ForwardSscCommand() return not successfull SCSI status 2!
11/20 1:18:42.340 7f0 C[da1], IN_LOGIN: iScsiConnection::receive: recvData returned 10058 (0x274a)!
11/20 1:18:42.340 160c S[da1]: iScsiSession::~iScsiSession: ~Session

Tue Nov 20, 2018 1:40 pm

Could you please collect the logs using this tool?
Please share them with us.

gnomesenpai · Tue Nov 20, 2018 2:38 pm

After about 15 hours and renaming .splumap and .spvmap the volume came up, however none of my esxi hosts can detect it anymore. Logs attached

http://fastdl.moevsmachine.tf/starwind.zip

Wed Nov 21, 2018 10:16 am

Please try to do the following steps: rescan storage, remove bindings and restart ESXi host.
I would recommend you to move data to IMAGE devices.

gnomesenpai · Wed Nov 21, 2018 10:28 pm

Tried, it picked up in static discovery however the drive its self is still not showing in esx, also tried using windows iscsi initiator, just shows up as inactive also.

Thu Nov 22, 2018 11:44 am

Could you please log a support case using this link?