[EAP 4.0.1 build 8137] Getting project sources not completing after 9 hours

Correction: it's been over 14 hours.

It's been over 38 hours now, so I created an issue in the Tracker (TW-6741)

Hello Michael,

   Unfortunately, the responsible developer won't be available until monday. I'll forward the issue to him.

   Sorry for inconvenience,
   KIR

Any update on this?  I need to get this issue resolved before the end of next week.

Thank you for feedback. Could you please attach logs from TC-tfs-native.exe process call. You may notice that process running under TeamCity server process.
To get the logs please do the following:

Copy to some folder tc-tfs-native.exe. This file can be found under TeamCity temp folder. The name would be TC-TFS-NATIVE-<some numbers>.exe .
Run this program with /log switch. To get command-line parameters help, run the process with no parameters.
Log files would be created under TEMP directory in TeamCity.NET folder. For each process new log file is created.

please start the process with the following commandline:

tfs-native.exe /log <http://server:port> /u:user /p:ppassowrd result.xml BuildPatch $/<TFS path> 0 c <some existing temp folder>

Please capture output from that process.
I believe that would be enough to run it for 10-15min

Please attach captured output and result.xml file
Thanks!

I followed your directions but didn't find a log file where I had specified the temp folder.  I then wrote the output of the console to the log file.  The error is included in that log file; the full stack trace is there.  I made some minor changes to the log file to omit the url, user id, and directory structure.

Thanks for your help.

Could you please check that you've used right url and tfs server path. Is that possible to work with TFS using some other clients from the same machine?
Thanks!

I double-checked the URL with a project that is currently working in TeamCity and they match.

Then I tried to go to the http site of the tfs server path manually.  When I try do so through Internet Explorer, it gives me a message "Error: Access Denied".

Does TeamCity need access through this web interface?  If so, why are the other 20 or so configurations working against that same server?

For me that is strage too. Could that be port, https. Do you use same settings for TeamCity? Could you please try to specify username in the way: domain\user.
Thanks!

OK, the problem was that I wasn't including the port.  The latest problem is with the results file:

C:\TEMP>TC-TFS-NATIVE-1230042624921.exe /log http://tfs.COMPANYNAME.com:8080
/u:DOMAIN\USERID /p:PASSWORD C:\Temp\Results\result.xml BuildPatch $/ROOT
0 c C:\Temp
DEBUG fs.Program - Tfs-native started with
TFS Native Verifier v4.0 Copyright (C) 2006-2008 JetBrains s.r.o.
INFO  fs.Program - Use Tfs from JetBrains.TeamCity.Tfs.Tfs8Accessor
TFS Native Accessor v4.0 Copyright (C) 2006-2008 JetBrains s.r.o.
INFO  fs.Program - Connecting to server http://tfs.radiantsystems.com:8080
Build Patch:
  Server='http://tfs.COMPANYNAME.com:8080'
  Username='USERNAME'
  Root='$/ROOT'
  FromVersion='0'
  CurrentVersion='c'
DEBUG temCommand - Start for item: $/ROOT
DEBUG tedCommand - Versions: 0 to 207095 item $/ROOT
ERROR fs.Program - System.Exception: The process cannot access the file 'result.
xml' because it is being used by another process. ---> System.IO.IOException: Th
e process cannot access the file 'result.xml' because it is being used by anothe
r process.
   at System.IO.Directory.DeleteHelper(String fullPath, String userPath, Boolean
recursive)
   at System.IO.Directory.Delete(String fullPath, String userPath, Boolean recur
sive)
   at JetBrains.TeamCity.Tfs.FileUtil.SafeDelete(String root) in C:\Agent\work\7
31b4fa04592c48d\tfs\native\TfsNativeAccessor\src\FileUtil.cs:line 26
   at JetBrains.TeamCity.Tfs.Command_BuildPatch.DoWithTfs(VersionControlServer v
cs, Int32 fromChangesetId, Int32 currentChangesetId) in C:\Agent\work\731b4fa045
92c48d\tfs\native\TfsNativeAccessor\src\Command_BuildPatch.cs:line 37
   at JetBrains.TeamCity.Tfs.ComplicatedCommand.DoWithTfs(VersionControlServer v
cs) in C:\Agent\work\731b4fa04592c48d\tfs\native\TfsNativeAccessor\src\Complicat
edCommand.cs:line 30
   at JetBrains.TeamCity.Tfs.Command_BuildPatch.DoWithTfs(VersionControlServer v
cs) in C:\Agent\work\731b4fa04592c48d\tfs\native\TfsNativeAccessor\src\Command_B
uildPatch.cs:line 28
   at JetBrains.TeamCity.Tfs.Command.Do() in C:\Agent\work\731b4fa04592c48d\tfs\
native\TfsNativeAccessor\src\Command.cs:line 29
   at JetBrains.TeamCity.Tfs.Program.Main(String[] args) in C:\Agent\work\731b4f
a04592c48d\tfs\native\TfsNativeAccessor\src\Program.cs:line 114
   --- End of inner exception stack trace ---
   at JetBrains.TeamCity.Tfs.Program.Main(String[] args) in C:\Agent\work\731b4f
a04592c48d\tfs\native\TfsNativeAccessor\src\Program.cs:line 143
System.Exception: The process cannot access the file 'result.xml' because it is
being used by another process. ---> System.IO.IOException: The process cannot ac
cess the file 'result.xml' because it is being used by another process.
   at System.IO.Directory.DeleteHelper(String fullPath, String userPath, Boolean
recursive)
   at System.IO.Directory.Delete(String fullPath, String userPath, Boolean recur
sive)
   at JetBrains.TeamCity.Tfs.FileUtil.SafeDelete(String root) in C:\Agent\work\7
31b4fa04592c48d\tfs\native\TfsNativeAccessor\src\FileUtil.cs:line 26
   at JetBrains.TeamCity.Tfs.Command_BuildPatch.DoWithTfs(VersionControlServer v
cs, Int32 fromChangesetId, Int32 currentChangesetId) in C:\Agent\work\731b4fa045
92c48d\tfs\native\TfsNativeAccessor\src\Command_BuildPatch.cs:line 37
   at JetBrains.TeamCity.Tfs.ComplicatedCommand.DoWithTfs(VersionControlServer v
cs) in C:\Agent\work\731b4fa04592c48d\tfs\native\TfsNativeAccessor\src\Complicat
edCommand.cs:line 30
   at JetBrains.TeamCity.Tfs.Command_BuildPatch.DoWithTfs(VersionControlServer v
cs) in C:\Agent\work\731b4fa04592c48d\tfs\native\TfsNativeAccessor\src\Command_B
uildPatch.cs:line 28
   at JetBrains.TeamCity.Tfs.Command.Do() in C:\Agent\work\731b4fa04592c48d\tfs\
native\TfsNativeAccessor\src\Command.cs:line 29
   at JetBrains.TeamCity.Tfs.Program.Main(String[] args) in C:\Agent\work\731b4f
a04592c48d\tfs\native\TfsNativeAccessor\src\Program.cs:line 114
   --- End of inner exception stack trace ---
   at JetBrains.TeamCity.Tfs.Program.Main(String[] args) in C:\Agent\work\731b4f
a04592c48d\tfs\native\TfsNativeAccessor\src\Program.cs:line 143

FYI, I tried the straight result.xml and got the same error.  So I created a C:\Temp\Results directory so I could make sure this wasn't due to other stuff hapening on the server.

Also, there were two TC-TFS executables in that directory.  I ran the both and got the same error.

Could you please create some other temp folder for the latest parameters.
For my example please create
C:\Temp\Results\ and
C:\Temp\Results\rrr filders.

TC-TFS-NATIVE-1230042624921.exe /log http://tfs.COMPANYNAME.com:8080 /u:DOMAIN\USERID /p:PASSWORD C:\Temp\Results\result.xml BuildPatch $/ROOT 0 c C:\Temp\Results\rrr

Thanks!

That worked.  I ran the process for 45 minutes because it did not appear to be hanging or have problems.  I have attached the results.xml file.

Another update: I went ahead and tried running the whole thing and it ran in less than 24 hours.  I have attached that results file zipped up.

I will be on holiday until Monday, but really need to get this issue solved by next Wednesday if I can (we just bought the enterprise license for this specific team and they're expecting it to work by the end of the year).  I will be checking my mail during my holiday and can help move this forward if needed.

Thank you for logs. Could you please include console output of TC-VSS-NATIVE too. I plan to implement more optimized way for clean patch. I'll send you a patch with it.
How muck time does it takes TC to collect changes?

Thanks!

I am now rerunning the process and writing the console output to a file.  I'll attach that shortly.  The other file is attached.

The process started at 6:34 pm and the results.xml file last was written to at 4:12 am, so it appears to have taken 9 hours and 45 minutes.

When I tried running this on the TeamCity server, I gave up after 67 hours.  So it appears that there is some difference between the process I ran manually and the one running on the server.

How much different version control settings do you have on TeamCity.
That seem time depends on the number of different VCS roots/different checkout rules. For each root and Checkout rules TeamCity checks out source files using TC-TFS-NATIVE util.

Thanks!

For this particular project, I have one VCS root going to the root TFS directory for this project:

$/RootDirectory

And three checkout rules:

+:Baseline/src=>src
+:ThirdParty=>ThirdParty
+:AnotherLibrary=>ThirdParty/AnotherLibrary

Does this answer your question?

Another thing I thought about that might help: Would you like me to run the process under a dotTrace profiler?

Yes. I think it would be helpful for me to analyze dotTrace snapshot from that run. Thanks!
Please attach the results to the issue in our tracker at http://www.jetbrains.net/tracker/issue/TW-6471

Thanks!

How long should I profile the application?  10 minutes?  The whole time?

Let's start from 10 minutes. But, please wait serveral minutes before starting to profile. Thanks!

The profile session was added to the issue last week.  Does this look like it can be addressed this week?  I'm trying to plan the rollout of this build and need to set expectations.

I've analyzed your log and found out that most of the time TC-VSS-NATIVE is downloading files. No we plan to implement TFS checkout on agent.
I'll send you a patch with that support as soon as possible. Please note, I will be on New Year hollidays from 31-th dec to 10-th jan.

The benefit of TFS on agent support is that it whould work using TFS Workspace, thus it would work faster and more relyable.

Thanks!

Thanks for the help with this.  I am looking forward to your patch.

Is there a simple explanation why when running the build through the TeamCity service it was still getting project sources after 67 hours but it completed after 9 hours when I ran it on the command line?  I'm fine with waiting nine hours, or even 90 if I need to, I just need it to complete.

Any update on this issue?  I'm stalling with the team that this is affecting.

Could you please try hotfix from the issue at http://www.jetbrains.net/tracker/issue/TW-6471
Thanks!

[Cross posted on TW-6471]

One thing I don't like about this solution is that it seems to be doing a full pull every time the build runs on that agent. I would expect it to do a full pull the first time but only pull differences from then on out. That basically adds 15 minutes to the build time which is not what I want. Is this the intended behavior?