Git submodule issues

After a few more experiments I "fix" it. At least for now.

I created a completely new configuration with a new VCS root. Regardless of the fact we have a user already in Fetch url (ssh://git@10.0.0.241/opt/git/EmsLib.git) I set it also in VCS root > Authentication settings > User name and the build is working again.

Still I have no idea what kind of magic git plugin does and I am afraid we will run to this kind of issues again.

Pavel

Hi Pavel,

do you still has a broken VCS root? Also does the old submodule repository is still available at the old url?

Let me explain how git-plugin works. When you create a git VCS root git-plugin reports current version of the repository to TeamCity. After that TeamCity periodically polls git-plugin and asks for changes between version TeamCity knows and the current version of the repository.

When git-plugin get request for collecting changes it traverse commits in the topological order and reports what files were changed in each commit. When plugin meets git submodule it tries to resolve submodule commit and report changes that were made in the submodule repository.

It is a common mistake to push change in the main repository that uses commit from submodule repository which wasn't pushed yet. In this case we cannot resolve submodule commit, so we try to go deeper in the history in order to find a valid submodule commit. When we find it we report content from the old valid commit in the place of broken one.

It seems like the history of you main repository looks like this:

o A // references a new submodule repository location
|
V
o B // references an old submodule repository location
|
V
... all older commits use old submodule repository location

In order to report changes between last 2 commits we need 2 trees for them, but we cannot build a tree for commit B since it uses an old submodule repository which is not available. So git-plugin traverses deeper in the history trying to find a valid submodule commit. And cannot find it.

This traversing is slow and produce a lot of warnings in the logs. This issue will be fixed within TW-17036, please watch/vote for it. Also, it seems like we have to limit this traversing through the history.

If you still has an old VCS root which cannot collect changes you can try to 'cure' it by making old submodule repository available. Please let me know did it helps.

Hi Dimitry,

thank you very much for you explanation. There are a few strange things with our setup that I don't understand.

1. I am sure there are at least a few correct submodules references in our project that were created after we moved our repository. I wouldn't be suprised if all of them are correct but probably there will be a few wrong ones.
2. The old repository is still accessible but as read only. Still, I was able to clone the old repository to the teamcity machine as teamcity user.

I think that the both points above should garantee that we will not see the log entries about corrupted commits or not thousands of them.

But after my yesterday "fix" in the morning it happened again. The same messages in the log. This time it didn't help to create a new VCS root I needed to clear caches (c:\Users\Administrator\.BuildServer\system\caches) and I deleted fetched repositories as well. Start team city and it is working now. So it worked yesterday for a few hours and this morning after a few pushes it stopped again.

Would you be so kind to answer me also these two questions that would maybe help me to move forward?

Is there a way how to enable logging to be able to see also which repository is used for retrieving submodules?

What is the starting point for git plugin to go trhough the process you described. I mean is it the head in that repository that the plugin takes and try to find a valid submodule?

Maybe the problem is that we didn't change only the location of the server for our git repository. We changed its protocol as well. From file to ssh  and now we are using the default private key authentication method.  Maybe that could be a problem that we have the old repository available but with different protocol only. But I can not do really much about it because we moved it from windows server to linux.


Regards,

Pavel

Hi Pavel,
answering to your questions:

Is there a way how to enable logging to be able to see also which repository is used for retrieving submodules?

I attached a build of plugin that logs details of submodules errors. To install it - copy zip into .BuildServer/plugins and restart the server.

What is the starting point for git plugin to go trhough the process you described. I mean is it the head in that repository that the plugin takes and try to find a valid submodule

The starting point is the last commit to the branch you set up in VCS root settings (by default it is master).

Pavel, could you please clarify: is the old submodule repository accessible through the old URL? If so, I guess my explanation from previous post is wrong.
If  submodule repository is not accessible through the old URL I think somebody pushed a merge commit which merges branches with old-submodule-URL commits. Is that possible?
If this is the case git-plugin will traverse such branch until it will not find commit with valid submodules. If branch was created before the moment you changed a git server, git-plugin will traverse a whole repository history. Now I'm trying to fix that. Fix will be available in one of 6.5 bugfix releases, also I will attach it to the http://youtrack.jetbrains.net/issue/TW-17036 when it will be ready.

Also to clarify why changing a username helped you: when you change any settings of VCS root TeamCity thinks it is a new VCS root, so it asks git-plugin about current version of repository and start collect changes from this revision. So changing VCS root settings makes TeamCity forget about old commits with submodule URL we cannot resolve.

Hi Dmitry,

I am sure the old path is accessible for reading. I run the git console as teamcity user which is used as credentials for team city web server service. I was able to clone both repositories (main and submodule).

I installed the plugin you attached. I could see one message (our wrong commit) "Ignore submodule error" but I still could not see the submodule url that tried to verify:

[2011-06-06 08:59:44,375]   WARN [{id=43} {id=43}] - les.SubmoduleAwareTreeIterator - Ignore submodule error: "Object 4f65a543b0e639a30f56e87ccac64b09bd40b6b2 is corrupt: Commit could not be resolved". It seems to be fixed in one of the later commits. 
[2011-06-06 09:06:32,272]   INFO [rmal executor 4] -      jetbrains.buildServer.VCS - Requesting patch: root=ssh://git@10.0.0.241/opt/git/EmsLib.git#branch_rel_1_3_91 {instance id=50, parent id=2}, cleanPatch=true, prevVersion=null, newVersion=72a418fdae3c3bcd92debb2b1ce4befdf6f8f816@1305f15d3e0, buildType=EMS :: Release Build 1.3.91 {id=bt3}, buildId=358 
[2011-06-06 09:07:59,862]   INFO [rmal executor 4] -      jetbrains.buildServer.VCS - Done requesting patch for root ssh://git@10.0.0.241/opt/git/EmsLib.git#branch_rel_1_3_91 {instance id=50, parent id=2} cleanPatch = true, prevVersion=null, newVersion=72a418fdae3c3bcd92debb2b1ce4befdf6f8f816@1305f15d3e0, buildId = 358; took 87 sec 583 msec 
[2011-06-06 09:08:43,062]   INFO [p-8080-3 /RPC2 ] -      jetbrains.buildServer.VCS - Patch applied for agent=WIN-R9C7IAFLQHS {host=127.0.0.1}, buildType=EMS :: Release Build 1.3.91 {id=bt3}, root=ssh://git@10.0.0.241/opt/git/EmsLib.git#branch_rel_1_3_91 {instance id=50, parent id=2}, version=72a418fdae3c3bcd92debb2b1ce4befdf6f8f816@1305f15d3e0 

Should I check different loggin file not the teamcity-vcs.log? I checked the pluging installation and can see that after restart the server creted c:\Users\Administrator\.BuildServer\plugins\.unpacked\jetbrains.git folder so I assume the installation was correct.

Regards,

Pavel

Hi Pavel,

you can check the version of plugin at Administration > Server Configuration > Plugins. It should be SNAPSHOT-20110603061831 for attached build of plugin. It is strange that you get this message, I will check my fix again.

As for submodule repository URL it seems I understood you wrong, I thought by "we have the old repository available but with different protocol only" you meant that URL is changed, because protocol is the part of the URL.

Hi Dmitry,

that was my mistake, I didn't know how to check the plugin version. I restarted teamcity webserver and teamcity build agent again and I am able to see correct version there.

We changed the url. The old url is accessible for reading. I just wanted to emphasize that we changed the protocol as well because I don't know if it makes difference for you.

Pavel,
I figured out one case when real cause of submodule error could be hidden in the logs. Could you please install an attached build of plugin and see if it helps with you problem?

Message was edited by: Dmitry Neverov

Hi Dmitry,

now it fails with no obvious reason. It complains about submodule but I can see it exists in remote repository on that branch. For example this one ab55814de48605399ca3ff6b64a9b138a6bee776 was made by my work-mate and I pulled the changes from remote and could see clearly that exists:

$ git log -1
commit ab55814de48605399ca3ff6b64a9b138a6bee776
Author: mot <mot@st-software.com>
Date:   Mon Jun 6 15:15:49 2011 +0200

    JIRA:
    GMSLIB-2359:        Access Control Export: add parameters of an badge

    - fix: when there are property collections, no projection is applied by filter builder

But teamcity is complaining VCS problem: EmsLib.git (branch_rel_1_3_91) you can find more in attached log file.

I think, now, it is worse then before but maybe I am missing something.

Pavel,

this is another example of bad logging from git-plugin, it will be fixed. Message like this:

"[2011-06-07 10:48:23,889]   WARN [{id=50} {id=50}] -      jetbrains.buildServer.VCS - Unable to collect changes for [EMS :: Release Build 1.3.91 {id=bt3}]: Error collecting changes for VCS root 'EmsLib.git (branch_rel_1_3_91)'
Collecting changes failed: org.eclipse.jgit.errors.CorruptObjectException: Object ab55814de48605399ca3ff6b64a9b138a6bee776 is corrupt: Commit could not be resolved: Unknown repository format "null"; expected "0".

means that repository of root EmsLib.git uses a submodule and bare repository of this submodule on TeamCity server has incorrect config file or do not have config file at all. Could you please check that all bare repositories inside .BuildServer/system/caches/git have config files and that config files has

[core]
    repositoryformatversion = 0

inside them? You can remove broken repositories, TeamCity will clone it again. Normally such situation should not happen, is it possible that someone remove/change config files?

Unfortunatelly I delete the caches before I read you reply. I am sure no one changed the config files in cache directory and in remote repository (I am the only one who could and I didn't). I can see repositoryformatversion = 0 in config files now.

I wanted to fix it so I stopped the teamcity web server, delete caches and delete checkout directories. I started TC and it didin't help. I did it again and also deleted git plugin (so the default version would be used) and it started to work suddenly. I will switch back to your plugin version this afternoon and test if we can see the problem again and I will check the config files then.

Hi Dmitry,

I updated git plugin to your latest. We haven't seen that submodule repetition from that time. But we had, I think three times, the common problem that someone pushed wrong submodule reference. The problem was that team city was not able to recover from that after someone else fixed it. Today I was able to collect all the logs and other files in moment it happened.

1. someone pushed our project with wrong sumbodule reference bb584011a03509ce0af342f8f88cc74f3fb0cff6 (log1)
2. project was fixed and with correct submodule 9bc983733d11526df28e6678a329cb603ed33727 and pushed to remote
3. the TC was not able to find that commit (log2) with error: Collecting changes failed: org.eclipse.jgit.errors.CorruptObjectException: Object 9bc983733d11526df28e6678a329cb603ed33727 is corrupt: Commit could not be resolved: Unknown repository format "null"; expected "0"
4. The .BuildServer/system/caches/git/git-C4F691E9.git (only subdirectory there) included only folders objects, refs (with partial content only or better to say almost empty)
   

What didn't help: changing the user for the VCS root
What helped: stop the TC web server, delete caches/git and start TC web server (Unfortunatelly I deleted also checkout directory for that VCS by mistake, I have no idea if it have any influence to make TC working again)

If you need any other information I am eager to provide them.

Pavel,

I'm trying understand what happened from the log.

[2011-06-07 16:31:19,243] TC collects changes between 6335373a4e1e96487d621ea547f2bff9688d3f0..88a0499dd24433886b0c21bf2d75d5d1ed709d35 (1 change), status OK - means that 88a0499dd24433886b0c21bf2d75d5d1ed709d35 has valid submodule reference.

[2011-06-07 17:26:04,511] -- [2011-06-07 17:35:32,734] TC several times tries to collects changes between 88a0499dd24433886b0c21bf2d75d5d1ed709d35..<some other commit>, status FAIL - means that <some other commit> has invalid submodule reference (bb584011a03509ce0af342f8f88cc74f3fb0cff6).

[2011-06-07 17:36:33,062] TC collects changes between 88a0499dd24433886b0c21bf2d75d5d1ed709d35..8aa56b62f3fd1f40528edaab37da916b4b8914bb (3 changes), status OK - means that 8aa56b62f3fd1f40528edaab37da916b4b8914bb has a valid submodule reference.

[2011-06-07 17:36:56,258] TC tries to build patch between 88a0499dd24433886b0c21bf2d75d5d1ed709d35..8aa56b62f3fd1f40528edaab37da916b4b8914bb, status FAIL - means that either 88a0499dd24433886b0c21bf2d75d5d1ed709d35 or 8aa56b62f3fd1f40528edaab37da916b4b8914bb has invalid submodule reference (bb584011a03509ce0af342f8f88cc74f3fb0cff6).

How is that possible? Do submodule commits referenced from 88a0499dd24433886b0c21bf2d75d5d1ed709d35 and 8aa56b62f3fd1f40528edaab37da916b4b8914bb are still available in submodule repository?
The only way I can explain it is that commits were available when TC collected changes and were erased when TC builds a patch. But I suppose you didn't do that.

After [2011-06-07 17:37:25,133] log1 contains nothing up to [2011-06-08 07:38:25,717], so I it is hard to say what is the reason of subsequent errors. The only thing I could say is that message:

[2011-06-08 07:47:26,468]   WARN [{id=48} {id=48}] -      jetbrains.buildServer.VCS - Unable to collect changes for [EMS :: CI Build {id=bt2}]: Error collecting changes for VCS root 'EmsLib.git (CI)'
Collecting changes failed: org.eclipse.jgit.errors.CorruptObjectException: Object 9bc983733d11526df28e6678a329cb603ed33727 is corrupt: Commit could not be resolved

means that submodule repository on TeamCity server exists and is valid, but doesn't contains commit 9bc983733d11526df28e6678a329cb603ed33727.

And after restart log2 shows that submodule repository config on TC server became broken.

You said you deleted checkout directory by mistake, what was the directory?
What is the URL of submodule repository? Maybe we mapped them to single bare repository on TC server.
I found that when we fetch submodule repository we use refspec '+refs/heads/*:refs/heads/*'. Do you track commit in submodule repository which is accessible from one of the refs/heads/<branch name>?

I am experiencing the same reocurring issues after upgrade to TeamCity 6.5:

[13:32:35]: Patch is broken, can be found in file: /Applications/buildAgent/temp/cache/temp5949030273039456543patch_20876

Are your repositories public? If so could you please provide their URLs so I can try to reproduce that?

The main repository is private but submodule commit with which error occurs (fa49ef9590161138cfff9fc54e0f843e1e8e5fcb) is from public repository git://gitorious.org/~mdes/qjson/mdes-qjson.git

Max,
could you please check if all repositories inside .BuildServer/system/caches/git have a file named 'config' and all configs have following inside:

[core]
    repositoryformatversion = 0

This directory is empty, no subdirectories nor files there at all. TeamCity is deployed on Windows, so the path looks like C:\TeamCity\delete_BuildServer\system\caches\git, is it right?

Usually it starts with Teamcity\.BuildServer. You can get the right path from 'Caches directory:' field at Administration > Server configuration > General.

Hi Dmitry,

we never delete commits from our repository (I even have no idea how to do that :) ) That means I checked these commits (with git show <commit>) 88a0499dd24433886b0c21bf2d75d5d1ed709d35 and 8aa56b62f3fd1f40528edaab37da916b4b8914bb and was able to see their comments.

I tried to go through our commits and find appropriate submodule version + information about what happen (newest on the top)



MAINPROJECT                              | SUBMODULE


THE TEAM CITY IS WORKING AGAIN
cd7fa4fbcd32607e2e0079a10e67c11919e5fed2 | bb584011a03509ce0af342f8f88cc74f3fb0cff6
36487ae6082d59bc35e2ff2a3bd86dbd90e7d645 | bb584011a03509ce0af342f8f88cc74f3fb0cff6
0124f597eed841a6078e7ce8c4220e74586c945e | bb584011a03509ce0af342f8f88cc74f3fb0cff6
MISSING SUBMODULE PUSHED BY OUR WORK-MATE
TRYING TO RUN IT AGAIN - IT'S NOT WORKING
82fefc27855217d26c65acee92af0079b09aa74a | 9bc983733d11526df28e6678a329cb603ed33727
PUSHING LAST WORKING SUBMODULE
8aa56b62f3fd1f40528edaab37da916b4b8914bb | bb584011a03509ce0af342f8f88cc74f3fb0cff6
6682601ee4fb6872327a670b6ff22b2cd7206eaf | bb584011a03509ce0af342f8f88cc74f3fb0cff6
8b444279f7905e6e6744f93d61cd84c33dfa4639 | bb584011a03509ce0af342f8f88cc74f3fb0cff6
BUILD BROKEN DOWN
88a0499dd24433886b0c21bf2d75d5d1ed709d35 | 9bc983733d11526df28e6678a329cb603ed33727
6335373a4e1e96487d621ea547f2bff9688d3f0a | 9bc983733d11526df28e6678a329cb603ed33727

I would gues that it could be connected to the state of the git cache because it was definitelly corrupted and the messages that the existing commit could not be found with error Unknown repository format "null" could indicate that.

Just checked this, found the right directory, one of the subdirectories doesn't have config file at all.  All other have config files with right content (repositoryformatversion = 0) though.

What is the right way to fix this?

How even it could happen?  Nobody messed with this repositories for sure, all was right before upgrade to 6.5.

Max,
I'm investigating that, but without success so far. As a workaround you can remove subdirs without config file, TeamCity will fetch these repositories again and should be able to build a patch after that.

Max,
trying to localize the bug: did you use branch remote-run trigger?

What exact trigger do you mean?  The only build trigger that we use is "VCS Trigger".

I did mean this, but this trigger seems to be unrelated.

I've removed that subdir without a config file, but now I have another problem. TeamCity says that it can't resolve a commit:

[13:28:25]: Patch is broken, can be found in file: /Applications/buildAgent/temp/cache/temp6273872578243258731patch_20945
[13:28:25]: Failed to build patch for build #1.0.0.84 {build id=20945}, VCS root: git@10.0.24.59:project#master {instance id=11629, parent id=131}, due to error: Patch building failed: org.eclipse.jgit.errors.CorruptObjectException: Object 64bf46b1e56595f8c9d98f6d20c46c454e7a267a is corrupt: Commit could not be resolved
jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl$1: Server was not able to build correct patch, most likely due to VCS errors, will try again.
     at jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl.throwError(PatchDownloaderImpl.java:113)
     at jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl.checkPatch(PatchDownloaderImpl.java:103)
     at jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl.copyPatchAndCheck(PatchDownloaderImpl.java:64)
     at jetbrains.buildServer.agent.impl.patch.UpdateSourcesPatcherBase.copyPatchToTempFile(UpdateSourcesPatcherBase.java:70)
     at jetbrains.buildServer.agent.impl.patch.UpdateSourcesFromServer.updateSources(UpdateSourcesFromServer.java:62)
     at jetbrains.buildServer.agent.impl.patch.UpdateSourcesBuildStageBase.doSourceUpdate(UpdateSourcesBuildStageBase.java:91)
     at jetbrains.buildServer.agent.impl.patch.UpdateSourcesBuildStageBase.doRecoverableStage(UpdateSourcesBuildStageBase.java:59)
     at jetbrains.buildServer.agent.impl.buildStages.startStages.RecoverableBuildStage.doLastAttempt(RecoverableBuildStage.java:112)
     at jetbrains.buildServer.agent.impl.buildStages.startStages.RecoverableBuildStage.doBuildStage(RecoverableBuildStage.java:70)
     at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:31)
     at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:29)
     at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.callRunStage(StagesExecutor.java:72)
     at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.doStages(StagesExecutor.java:35)
     at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor.doStages(BuildStagesExecutor.java:24)
     at jetbrains.buildServer.agent.impl.BuildRunAction.doStages(BuildRunAction.java:64)
     at jetbrains.buildServer.agent.impl.BuildRunAction.runBuild(BuildRunAction.java:51)
     at jetbrains.buildServer.agent.impl.BuildAgentImpl.doActualBuild(BuildAgentImpl.java:246)
     at jetbrains.buildServer.agent.impl.BuildAgentImpl.access$100(BuildAgentImpl.java:49)
     at jetbrains.buildServer.agent.impl.BuildAgentImpl$1.run(BuildAgentImpl.java:219)
     at java.lang.Thread.run(Thread.java:680)
Caused by: jetbrains.buildServer.vcs.patches.UnsuccessfulPatchException: Failed to build patch for build #1.0.0.84 {build id=20945}, VCS root: git@10.0.24.59:project#master {instance id=11629, parent id=131}, due to error: Patch building failed: org.eclipse.jgit.errors.CorruptObjectException: Object 64bf46b1e56595f8c9d98f6d20c46c454e7a267a is corrupt: Commit could not be resolved
     at jetbrains.buildServer.vcs.patches.AbstractPatcher$1.fail(AbstractPatcher.java:93)
     at jetbrains.buildServer.vcs.patches.LowLevelPatcher.readPatchStream(LowLevelPatcher.java:156)
     at jetbrains.buildServer.vcs.patches.LowLevelPatcher.applyPatch(LowLevelPatcher.java:79)
     at jetbrains.buildServer.vcs.patches.AbstractPatcher.applyPatch(AbstractPatcher.java:42)
     at jetbrains.buildServer.agent.impl.patch.PatchApplierImpl.applyPatch(PatchApplierImpl.java:18)
     at jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl.checkPatchInFileIsCompleted(PatchDownloaderImpl.java:83)
     at jetbrains.buildServer.agent.impl.patch.PatchDownloaderImpl.checkPatch(PatchDownloaderImpl.java:93)
     ... 18 more 

I've checked and it turns out that this commit is a merge commit.  Again, I must say that this submodule is cloned from a public URL from a public repository (git://github.com/MaxMotovilov/adstream-js-frameworks.git) and as you can see that repository really has that commit so it's definitely abnormal behavior.

Max,
I added some debug logs, could you please install an attached build of plugin, restart TeamCity, enable 'debug-vcs' logging preset at Administration > Server Configuration > Diagnostics and provide a teamcity-vcs.log for the time when error occurs?

Max,
did you have a time to try it?

Where exactly teamcity-vcs.log should be located?