Connection problems

robinz · Post by **robinz** » Wed Mar 29, 2006 2:29 pm

Quite frequently (10-15 times a day) we are having connection problems with Vault from within VS.Net 2003. This can occur while opening a project, checking out, or getting latest version. Typically the IDE hangs for 30 seconds or so and then we get a message like this:

The Vault server could not be contacted to perform the operation. Your network connection to the server may have been interrupted. Please verify your network settings using the Options dialog under the Tools menu in the Vauult GUI Client. The underlying connection was closed: An unexpected error occurred on a receive.

Most of the time if you immediately retry the operation it succeds.

Where should we start to diagnose this problem?

dan · Post by **dan** » Wed Mar 29, 2006 3:31 pm

A few questions/comments to get started:

1. What version of Vault client/server are you running?
2. Does this happen with the GUI client as well, or only the IDE client?
3. Does it happen on different workstations, and does it happen on remote vs local machines?
4. You might want to turn on client logging and see if there is more info in the log files. See http://support.sourcegear.com/viewtopic.php?t=2898 for more info.

Usually problems like this are due to network issues rather than Vault, such as firewalls or proxies or IIS on the server side timing out the connection.

robinz · Post by **robinz** » Wed Mar 29, 2006 3:44 pm

1) 3.1.6
2) Both the GUI and the IDE
3) Different workstations, local and remote
4) I'll try that

dan · Post by **dan** » Wed Mar 29, 2006 3:59 pm

Is your server running IIS 6 (windows server 2003?). If so, take a look at this KB article: http://support.sourcegear.com/viewtopic.php?t=1014

You might also check the Vault server log (%windir%/temp/sgvault) to see if there is any info in there. It will show when users login and logout, so you could verify the sessions are being terminated that way.

robinz · Post by **robinz** » Wed Mar 29, 2006 4:03 pm

What classes should I be logging?

robinz · Post by **robinz** » Wed Mar 29, 2006 4:11 pm

At 3/29/06 4:07 pm I received an error in the IDE. I'm not seeing anything in the log about the error...here is the log:

3/29/2006 4:06:25 PM <ide>: [<No Name>:3128] [SCCOpenProject] bCreateIfNew=False, bSilentOpen=False, projectName="$/Apps", localPath="C:\Apps", serverPathAndProfile="http://myserver/VaultService|", storedRepID="1"
3/29/2006 4:06:25 PM <refresh>: [<No Name>:3128] Refresh started
3/29/2006 4:06:25 PM <refresh>: [<No Name>:3128] delta passed in was null, retrieving one
3/29/2006 4:06:25 PM <refresh>: [<No Name>:3128] calling GetRepositoryStructure(1, 63007, -1, ref, 7/1/1850 12:00:00 AM)
3/29/2006 4:06:25 PM <connection>: [<No Name>:3128] GetRepositoryStructure started.
3/29/2006 4:06:25 PM <refresh>: [<No Name>:3128] GetRepositoryStructure started
3/29/2006 4:06:25 PM <refresh>: [<No Name>:3128] Calling client service GetRepositoryStructure(1, 63007, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/29/2006 4:07:03 PM <refresh>: [<No Name>:3128] GetRepositoryStructure finished
3/29/2006 4:07:03 PM <refresh>: [<No Name>:3128] Refresh finished
3/29/2006 4:07:12 PM <ide>: [<No Name>:3128] [SCCOpenProject] bCreateIfNew=False, bSilentOpen=False, projectName="$/Apps", localPath="C:\Apps", serverPathAndProfile="http://myserver/VaultService|", storedRepID="1"
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Refresh started
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] delta passed in was null, retrieving one
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] calling GetRepositoryStructure(1, 63007, -1, ref, 7/1/1850 12:00:00 AM)
3/29/2006 4:07:12 PM <connection>: [<No Name>:3128] GetRepositoryStructure started.
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] GetRepositoryStructure started
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Calling client service GetRepositoryStructure(1, 63007, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Client service GetRepositoryStructure returned: dtLatestCheck 7/1/1850 12:00:00 AM, nReturnDestRevision 63007, rd not null True
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] GetRepositoryStructure finished
3/29/2006 4:07:12 PM <connection>: [<No Name>:3128] GetRepositoryStructure finished.
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Took mutex 1628
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Released mutex 1628
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] GetRepositoryStructure returned: returnedRevision 63007, newLatestDate 7/1/1850 12:00:00 AM, delta not null: True
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] RefreshCheckOutList started
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] Call GetCheckOutListChanges(Rep 1, Rev 48840, LastUpdt 6/30/1850 11:00:00 PM)
3/29/2006 4:07:12 PM <connection>: [<No Name>:3128] GetCheckOutListChanges started.
3/29/2006 4:07:12 PM <connection>: [<No Name>:3128] GetCheckOutListChanges finished.
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] GetCheckOutListChanges returned: Rev 48840 completeList False, newLastUpdt 6/30/1850 11:00:00 PM
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] New items:
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] <null>
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] Release items:
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] <null>
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] Source and target check out list revisions are both 48840, and last locking date match. Returning with no update
3/29/2006 4:07:12 PM <checkoutlist>: [<No Name>:3128] RefreshCheckOutList finished
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Calling Repository.Update with delta
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Took mutex 1396
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] SaveIfNothingOnDisk: not saving
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Released mutex 1396
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Refreshing working folder associations from disk
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Took mutex 1448
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Released mutex 1448
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Refreshing all change set items without notify
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Took mutex 1484
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Released mutex 1484
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Took mutex 1600
3/29/2006 4:07:12 PM <mutex>: [<No Name>:3128] Released mutex 1600
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Calling UpdateKnownChanges_RefreshKnown with notify
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Calling NotifyTreeStructureChanged
3/29/2006 4:07:12 PM <refresh>: [<No Name>:3128] Refresh finished
3/29/2006 4:07:13 PM <ide>: [<No Name>:3128] [SCCGetFileStatus] userName="myusername", fileName="KeyFixer.sln", projectName="$/Apps", workingDir="C:\Apps"
3/29/2006 4:07:13 PM <ide>: [<No Name>:3128] [SCCGetFileStatus] userName="myusername", fileName="KeyFixer.vssscc", projectName="$/Apps", workingDir="C:\Apps"

robinz · Post by **robinz** » Wed Mar 29, 2006 4:19 pm

It occured again at 4:17 attempting to do a checkout:

3/29/2006 4:16:39 PM <ide>: [<No Name>:3128] [SCCDiff] fileName="AppCon.vb", projectName="$/Apps/KeyFixerProjects/KeyFixer", workingDir="C:\Apps\KeyFixerProjects\KeyFixer", bShowDiffDialog=False
3/29/2006 4:16:39 PM <refresh>: [<No Name>:3128] Refresh started
3/29/2006 4:16:39 PM <refresh>: [<No Name>:3128] delta passed in was null, retrieving one
3/29/2006 4:16:39 PM <refresh>: [<No Name>:3128] calling GetRepositoryStructure(1, 63007, -1, ref, 7/1/1850 12:00:00 AM)
3/29/2006 4:16:39 PM <connection>: [<No Name>:3128] GetRepositoryStructure started.
3/29/2006 4:16:39 PM <refresh>: [<No Name>:3128] GetRepositoryStructure started
3/29/2006 4:16:39 PM <refresh>: [<No Name>:3128] Calling client service GetRepositoryStructure(1, 63007, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/29/2006 4:17:17 PM <refresh>: [<No Name>:3128] GetRepositoryStructure finished
3/29/2006 4:17:17 PM <refresh>: [<No Name>:3128] Refresh finished

robinz · Post by **robinz** » Wed Mar 29, 2006 4:34 pm

Here is one from the GUIClient @ 4:33...the previous 2 were from the VS IDE:

3/29/2006 4:31:16 PM <mutex>: [GUIClientWorkerThread:804] Took mutex 1088
3/29/2006 4:31:16 PM <mutex>: [GUIClientWorkerThread:804] Released mutex 1088
3/29/2006 4:31:16 PM <mutex>: [GUIClientWorkerThread:804] Took mutex 1092
3/29/2006 4:31:16 PM <mutex>: [GUIClientWorkerThread:804] Released mutex 1092
3/29/2006 4:31:26 PM <refresh>: [GUIClientWorkerThread:804] Refresh started
3/29/2006 4:31:26 PM <refresh>: [GUIClientWorkerThread:804] delta passed in was null, retrieving one
3/29/2006 4:31:26 PM <refresh>: [GUIClientWorkerThread:804] calling GetRepositoryStructure(1, 63009, -1, ref, 7/1/1850 12:00:00 AM)
3/29/2006 4:31:26 PM <connection>: [GUIClientWorkerThread:804] GetRepositoryStructure started.
3/29/2006 4:31:26 PM <refresh>: [GUIClientWorkerThread:804] GetRepositoryStructure started
3/29/2006 4:31:26 PM <refresh>: [GUIClientWorkerThread:804] Calling client service GetRepositoryStructure(1, 63009, -1, 7/1/1850 12:00:00 AM, ref, ref, ref)
3/29/2006 4:32:55 PM <refresh>: [GUIClientWorkerThread:804] GetRepositoryStructure finished
3/29/2006 4:32:55 PM <refresh>: [GUIClientWorkerThread:804] Refresh finished

dan · Post by **dan** » Wed Mar 29, 2006 4:38 pm

If you are running Win2K3 on the server, take a look at that KB article, because it is likely timing out your sessions.

robinz · Post by **robinz** » Wed Mar 29, 2006 5:08 pm

We're running win2k sp 4.

robinz · Post by **robinz** » Thu Mar 30, 2006 7:05 am

I looked at the server logs. They are showing a lot more logins than logouts. On 3/29 there were 29 logins, but only 5 logouts.

dan · Post by **dan** » Thu Mar 30, 2006 7:30 am

That makes sense - if the connection is being dropped, there wouldn't be a logout.

Did this just start happening recently, and if so does it correspond to a change in your network?

Also, are you on the same LAN as the server, or is it a remote connection or a VPN of some kind?

robinz · Post by **robinz** » Thu Mar 30, 2006 7:54 am

It has happened from the very begining. I was in such a hurry to get off of Visual Source Safe to Vault, I didn't take the time to figure out what the problem was. Even with these issues Vault is way better

!

It happens both locally and remotely. We connect directly to the box over HTTP, there is no VPN.

dan · Post by **dan** » Thu Mar 30, 2006 9:06 am

Have you checked both the Vault Admin Tool and IIS settings to make sure the sessions are not being timed out after 10 minutes or so?

robinz · Post by **robinz** » Thu Mar 30, 2006 9:16 am

Vault Admin tool | Server Options | Vault Session Timeout is set to 4320.

In IIS, under site properties, the Web Site | connection Timeout is set to 900 seconds.