I'm using vSAN Free with the latest version (StarWind Virtual Storage Appliance v8.0.0 (Build 15260, [SwVSA], Win64) )
So far, I'm not using replicated SAN storage because of some occasional reliability issues, instead I'm just using a plain local, non synchronized, NAS image to build a large datastore for backup purpose.
It was working fine, but a few days ago, after updating vSphere with the latest patches, after reboot, I'm getting frenquently (every few hours) those warnings in Starwind logs (each time I get 6 of them within a minute):
"Old session with the same ID is still present. Login rejected! Please try to reconnect Initiator."
More detailed logs when this occur:
9/19 7:24:01.463632 33 IMG: *** ImageFile_ScsiExec: SCSIOP (0x85) is not supported.
9/19 7:29:09.269444 7a IMG: ImageFile_IoCompleted: Warning(Time FileIO): request(0x0000000003024CA0) ssc(0x0000000003242948) function(Execute SCSI Command) opCode(0x8A), timeFileIO = 5229 ms, g_cmdE
ecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:29:09.269591 7a IMG: ImageFile_ScsiCompleteRequest: Warning(Time Request EXEC): request(0x0000000003024CA0) ssc(0x0000000003242948) function(Execute SCSI Command) opCode(0x8A), timeExecReques
= 5229 ms, g_cmdExecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:29:09.269613 7a IMG: ImageFile_ScsiCompleteRequest: Warning(Time Request EXEC): request(0x0000000003026F90) ssc(0x000000000181BE00) function(Execute SCSI Command) opCode(0x8A), timeExecReques
= 5229 ms, g_cmdExecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:29:09.269875 7a IMG: ImageFile_IoCompleted: Warning(Time FileIO): request(0x0000000003023D30) ssc(0x0000000003244D08) function(Execute SCSI Command) opCode(0x8A), timeFileIO = 3749 ms, g_cmdE
ecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:29:09.269894 7a IMG: ImageFile_ScsiCompleteRequest: Warning(Time Request EXEC): request(0x0000000003023D30) ssc(0x0000000003244D08) function(Execute SCSI Command) opCode(0x8A), timeExecReques
= 3749 ms, g_cmdExecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:29:09.269915 7a IMG: ImageFile_ScsiCompleteRequest: Warning(Time Request EXEC): request(0x00000000030291B0) ssc(0x000000000300F8C0) function(Execute SCSI Command) opCode(0x2A), timeExecReques
= 3749 ms, g_cmdExecTimeWarningLimitInSec = 3 s. Device: 'C:\StarWind\storage\mnt\NVMe\nas110\nas110.img'
9/19 7:33:07.534675 100 T[1c,14c8dc]: iScsiTask::handleTaskMgmtCmd: Management command: abort task (CmdSN 26857391, ITT 0xe3cf9901) not found.
9/19 7:33:17.536294 100 T[1c,14c8de]: iScsiTask::handleTaskMgmtCmd: Management command: abort task (CmdSN 26857391, ITT 0xe3cf9901) not found.
9/19 7:33:23.485453 100 C[1c], LIN: iScsiConnection::recvData: Recv - peer shutdown
9/19 7:33:23.485527 100 C[1c], LIN: iScsiConnection::receive: recvData returned error 10058 (0x274a)!
9/19 7:33:23.486329 100 C[1c], LIN: iScsiConnection::recvWorker: *** 'recv' thread: recv failed 10058.
9/19 7:33:23.487119 101 Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:23.487345 101 Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:26.016227 9 Srv: iScsiServer::listenConnections: Accepted iSCSI connection from a.b.c.1:18272 to a.b.c.10:3260. (Id = 0x1d)
9/19 7:33:26.016299 9 S[1d]: iScsiSession::iScsiSession: Session (00000000010FA180)
9/19 7:33:26.016314 9 C[1d], FREE: iScsiConnection::doTransition: Event - CONNECTED.
9/19 7:33:26.266138 1db C[1d], XPT_UP: iScsiConnection::handleFirstLogin: Login request: ISID 0x00023d000001, TSIH 0x0000.
9/19 7:33:26.266221 1db C[1d], XPT_UP: iScsiConnection::doTransition: Event - LOGIN.
9/19 7:33:26.266296 1db Params: iScsiParameter::update: <<< String param 'InitiatorName': received 'iqn.1998-01.com.vmware:xxxxxxxxxxxxxxxxxxxxxxxxxxxx:1242115180:64', accepted 'iqn.1998-01.com.vmwar
:xxxxxxxxxxxxxxxxxxxxxxxxxxxx:1242115180:64'
9/19 7:33:26.266317 1db Params: iScsiParameter::update: <<< String param 'InitiatorAlias': received 'iscsi_vmk', accepted 'iscsi_vmk'
9/19 7:33:26.266346 1db Params: iScsiParameter::update: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:192.168.1.10-nas110', accepted 'iqn.2008-08.com.starwindsoftware:192
168.1.10-nas110'
9/19 7:33:26.266359 1db Params: iScsiParameter::update: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
9/19 7:33:26.266370 1db Params: iScsiParameter::update: <<< Enum param 'HeaderDigest': received 'None', accepted 'None'
9/19 7:33:26.266383 1db Params: iScsiParameter::update: <<< Enum param 'DataDigest': received 'None', accepted 'None'
9/19 7:33:26.266397 1db Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
9/19 7:33:26.266409 1db Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
9/19 7:33:26.266420 1db Params: iScsiParameter::update: <<< Boolean param 'IFMarker': received No, accepted 0
9/19 7:33:26.266434 1db Params: iScsiParameter::update: <<< Boolean param 'OFMarker': received No, accepted 0
9/19 7:33:26.266447 1db Params: iScsiParameter::update: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
9/19 7:33:26.266461 1db Params: iScsiParameter::update: <<< Boolean param 'InitialR2T': received No, accepted 0
9/19 7:33:26.266475 1db Params: iScsiParameter::update: <<< Boolean param 'ImmediateData': received Yes, accepted 1
9/19 7:33:26.266489 1db Params: iScsiParameter::update: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
9/19 7:33:26.266501 1db Params: iScsiParameter::update: <<< Numeric param 'FirstBurstLength': received 262144, accepted 262144
9/19 7:33:26.266512 1db Params: iScsiParameter::update: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
9/19 7:33:26.266525 1db Params: iScsiParameter::update: <<< Numeric param 'MaxConnections': received 1, accepted 1
9/19 7:33:26.266537 1db Params: iScsiParameter::update: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
9/19 7:33:26.266548 1db Params: iScsiParameter::update: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
9/19 7:33:26.266561 1db Params: iScsiParameter::update: <<< Numeric param 'MaxRecvDataSegmentLength': received 131072, accepted 131072
9/19 7:33:26.273537 1db T[1d,1]: iScsiTask::startLoginPhase: An old session [1c] from the same Initiator/ISID is there. Session reinstatement starting...
9/19 7:33:26.273570 1db S[1c]: iScsiSession::freeHanged: Exec queue is not empty (8 tasks)!
9/19 7:33:26.293942 1db Srv: *** SwSocket::Shutdown: shutdown() failed with error 10038!
9/19 7:33:26.293974 1db C[1c], LIN: iScsiConnection::terminate: Closing socket.
9/19 7:33:27.295697 1db T[1d,1]: iScsiTask::startLoginPhase: Old session [1c] to target 'iqn.2008-08.com.starwindsoftware:192.168.1.10-nas110' is still present. Login rejected!
9/19 7:33:27.295778 1db func: >>> iScsiServer::sendNotification
9/19 7:33:27.295790 1db func: >>> CEventDataBase::AddRecord
9/19 7:33:27.295800 1db EventDB: CEventDataBase::AddRecord: Code 275, severity 2, additional strings: 2
9/19 7:33:27.295838 1db func: <<< CEventDataBase::AddRecord
9/19 7:33:27.295848 1db Srv: iScsiServer::sendNotification: Send reaction start (reaction type 2, msg code 275).
9/19 7:33:27.295866 1db Srv: iScsiServer::sendNotification: Send reaction finish.
9/19 7:33:27.295876 1db Srv: iScsiServer::sendNotification: Send reaction start (reaction type 1, msg code 275).
9/19 7:33:27.296496 1db Srv: iScsiServer::sendNotification: Send reaction finish.
9/19 7:33:27.296524 1db Srv: iScsiServer::sendNotification: Send reaction start (reaction type 3, msg code 275).
9/19 7:33:27.296669 1db Srv: iScsiServer::sendNotification: Send reaction finish.
9/19 7:33:27.296688 1db func: <<< iScsiServer::sendNotification
9/19 7:33:27.296910 1d9 C[1d], IN_LOGIN: iScsiConnection::doTransition: Event - LOGIN_REJECT.
9/19 7:33:27.297272 1d9 Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:27.549891 1db C[1d], IN_LOGIN: iScsiConnection::recvData: Recv - peer shutdown
9/19 7:33:27.549968 1db C[1d], IN_LOGIN: iScsiConnection::receive: recvData returned error 10058 (0x274a)!
9/19 7:33:27.550068 1db Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:27.550176 1db Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:27.550225 1db Srv: *** SwSocket::Shutdown: shutdown() failed with error 10058!
9/19 7:33:27.550305 1d4 S[1d]: iScsiSession::~iScsiSession: ~Session
9/19 7:33:29.828985 9 Srv: iScsiServer::listenConnections: Accepted iSCSI connection from a.b.c.1:44720 to a.b.c.10:3260. (Id = 0x1e)
9/19 7:33:29.829058 9 S[1e]: iScsiSession::iScsiSession: Session (00000000018208C0)
9/19 7:33:29.829073 9 C[1e], FREE: iScsiConnection::doTransition: Event - CONNECTED.
9/19 7:33:30.080522 1d8 C[1e], XPT_UP: iScsiConnection::handleFirstLogin: Login request: ISID 0x00023d000001, TSIH 0x0000.
9/19 7:33:30.080622 1d8 C[1e], XPT_UP: iScsiConnection::doTransition: Event - LOGIN.
9/19 7:33:30.080689 1d8 Params: iScsiParameter::update: <<< String param 'InitiatorName': received 'iqn.1998-01.com.vmware:xxxxxxxxxxxxxxxxxxxxxxxxxxxx:1242115180:64', accepted 'iqn.1998-01.com.vmwar
:xxxxxxxxxxxxxxxxxxxxxxxxxxxx:1242115180:64'
9/19 7:33:30.080713 1d8 Params: iScsiParameter::update: <<< String param 'InitiatorAlias': received 'iscsi_vmk', accepted 'iscsi_vmk'
9/19 7:33:30.080750 1d8 Params: iScsiParameter::update: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:192.168.1.10-nas110', accepted 'iqn.2008-08.com.starwindsoftware:192
168.1.10-nas110'
9/19 7:33:30.080766 1d8 Params: iScsiParameter::update: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
9/19 7:33:30.080779 1d8 Params: iScsiParameter::update: <<< Enum param 'HeaderDigest': received 'None', accepted 'None'
9/19 7:33:30.080793 1d8 Params: iScsiParameter::update: <<< Enum param 'DataDigest': received 'None', accepted 'None'
9/19 7:33:30.080809 1d8 Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Wait': received 2, accepted 2
9/19 7:33:30.080821 1d8 Params: iScsiParameter::update: <<< Numeric param 'DefaultTime2Retain': received 0, accepted 0
9/19 7:33:30.080833 1d8 Params: iScsiParameter::update: <<< Boolean param 'IFMarker': received No, accepted 0
9/19 7:33:30.080846 1d8 Params: iScsiParameter::update: <<< Boolean param 'OFMarker': received No, accepted 0
9/19 7:33:30.080860 1d8 Params: iScsiParameter::update: <<< Numeric param 'ErrorRecoveryLevel': received 0, accepted 0
9/19 7:33:30.080871 1d8 Params: iScsiParameter::update: <<< Boolean param 'InitialR2T': received No, accepted 0
9/19 7:33:30.080885 1d8 Params: iScsiParameter::update: <<< Boolean param 'ImmediateData': received Yes, accepted 1
9/19 7:33:30.080899 1d8 Params: iScsiParameter::update: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
9/19 7:33:30.080910 1d8 Params: iScsiParameter::update: <<< Numeric param 'FirstBurstLength': received 262144, accepted 262144
9/19 7:33:30.080920 1d8 Params: iScsiParameter::update: <<< Numeric param 'MaxOutstandingR2T': received 1, accepted 1
9/19 7:33:30.080932 1d8 Params: iScsiParameter::update: <<< Numeric param 'MaxConnections': received 1, accepted 1
9/19 7:33:30.080941 1d8 Params: iScsiParameter::update: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
9/19 7:33:30.080951 1d8 Params: iScsiParameter::update: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
9/19 7:33:30.080962 1d8 Params: iScsiParameter::update: <<< Numeric param 'MaxRecvDataSegmentLength': received 131072, accepted 131072
9/19 7:33:30.086793 1d8 T[1e,1]: iScsiTask::startLoginPhase: An old session [1c] from the same Initiator/ISID is there. Session reinstatement starting...
9/19 7:33:30.086807 1d8 S[1c]: iScsiSession::freeHanged: Exec queue is not empty (8 tasks)!
9/19 7:33:30.107097 1d8 Srv: *** SwSocket::Shutdown: shutdown() failed with error 10038!
9/19 7:33:30.107123 1d8 C[1c], LIN: iScsiConnection::terminate: Closing socket.
9/19 7:33:31.109563 1d8 T[1e,1]: iScsiTask::startLoginPhase: Old session [1c] to target 'iqn.2008-08.com.starwindsoftware:192.168.1.10-nas110' is still present. Login rejected!
9/19 7:33:31.109645 1d8 func: >>> iScsiServer::sendNotification
9/19 7:33:31.109658 1d8 func: >>> CEventDataBase::AddRecord
9/19 7:33:31.109670 1d8 EventDB: CEventDataBase::AddRecord: Code 275, severity 2, additional strings: 2
...
How to avoid getting multiple copies of those warnings and what triggered them to start with, and can we avoid the problem at all?
The Latest Gartner® Magic Quadrant™Hyperconverged Infrastructure Software