TC and maven snapshot trigger

Hello,
I understand that the question is pretty general, so I will provide you two log snippets and the question is, why the behaviour is different (I've upgraded to 6.5.2 btw.)?

TeamCity is up and running, and I deploy new snapshot into the maven remote repository (and wait for the artifact digest cache expiration - first line of snippet):

[snip]
[2011-07-29 06:39:46,313] DEBUG - jetbrains.buildServer.maven.acd.CachingDigestRetriever$DigestResult - Cached value for request x.y.z:email:jar:1.1-SNAPSHOT is out of date or doesn't exist
[2011-07-29 06:39:46,316] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Retrieving digest for x.y.z:email:jar:1.1-SNAPSHOT:compile
[2011-07-29 06:39:46,317] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Looking into Repository[barcap-muni-snapshots|http://nyfilx314.abc.com:8081/maven/content/repositories/barcap-muni-snapshots]
[2011-07-29 06:39:46,347] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - SHA-1 digest found
[2011-07-29 06:39:46,354] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Found: bbd842aadd7e82ee914023459f5389b66b47dad9 SHA-1
[2011-07-29 06:39:46,356] DEBUG - jetbrains.buildServer.maven.acd.Checker - Retrieved digest: bbd842aadd7e82ee914023459f5389b66b47dad9 SHA-1
[/snip]

and after the TC is restarted (nothing else has been changed)

[snip]
[2011-07-29 06:52:29,960] DEBUG - jetbrains.buildServer.maven.acd.CachingDigestRetriever$DigestResult - Cached value for request x.y.z:email:jar:1.1-SNAPSHOT is out of date or doesn't exist
[2011-07-29 06:52:30,316] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Retrieving digest for x.y.z:email:jar:1.1-SNAPSHOT:compile
[2011-07-29 06:52:30,316] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Looking into Repository[barcap-muni-snapshots|http://nyfilx314.abc.com:8081/maven/content/repositories/barcap-muni-snapshots]
[2011-07-29 06:52:30,352] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - SHA-1 digest found
[2011-07-29 06:52:30,357] DEBUG - jetbrains.buildServer.maven.acd.WagonDigestRetriever - Found: e86fdda0e03c9cf039a1d593f74f2f1155ef0193 SHA-1
[2011-07-29 06:52:30,360] DEBUG - jetbrains.buildServer.maven.acd.Checker - Retrieved digest: e86fdda0e03c9cf039a1d593f74f2f1155ef0193 SHA-1
[/snip]

Thanks for your help

Milan

Hi Milan,

By default TeamCity caches once retrieved digests for 10 minutes to avoid heavy load on the repository manager. That's why you might see an old digest value in the log even when you have updated the latest snapshot just before that. But this effect should not last more than 10 minutes. The default polling interval of the checker is also about 10 minutes and it's not sychronized with the caching interval. So the maximum possible latency of the trigger should not exceed 20 minutes.

Both interval settings are adjustable with corresponding system properties. But they aren't documented and there is no guarantee they will be kept in future versions. I can provide you with these properties if you absolutely need it.

If your build isn't triggered more than 20 minutes after the actual snapshot update and you didn't change any default settings, then this is most likely a bug, and I would appreciate if you provide more details on this.

Thank you!

Hi Sergey,

I'm aware of the caching interval and once it expires it makes a record to the log (Cached value for request ... is out of date or doesn't exist) - I have them in the log snippets. The rebuild doesn't happen in far more than 20 minutes then.

I tried the new jars you provided me, but it didn't help and I belive it is different issue, than the desribed one.

I really suspect the WagonDigestRetriever class, as it doesn't return the latest hash, even it is asked to.

If you need any other details, feel free to ask, I'll be glad to contribute.

Thanks for your help Milan

Milan,

I've attached maven-runner-server.jar with more logging. Please replace the existing one and enable debug logging as described in the last comment of http://youtrack.jetbrains.net/issue/TW-17129
Then deploy a new snapshot to the repository, and send me maven-debug.log.

To avoid the need to wait for cache expiration please add the following lines into the file <TC data dir>/config/internal.properties

teamcity.maven.artifactTrigger.checkInterval=60
teamcity.maven.artifactTrigger.timeToCache=0

Please do it before you restart the server. Thank you.

Sergey,

I tried the jar you attached, did the required changes in property file, changed logging etc. And the state is, that maven snapshot triggering started to work suddenly, unfortunatelly from time to time I can see the ugly red warning:  Problem with Maven Snapshot Dependencies... (probably the same isuue as in http://youtrack.jetbrains.net/issue/TW-17129).  

The warning disapears after some time and maybe I will be able to tune it up - now it is usable for us. I can still provide you the maven log, but not sure if you are interested now.

My current plan is start from scratch and will try identify the critical change (jar, property file change) and will try to avoid the warning message.

Thanks Milan

Hi,

the log has been sent to your private mailbox. Will continue with investigation tomorrow.

Thanks Milan

Hi Milan,

Pavel told me you're still having "ugly warning" form time to time. Unfortunately the log you've sent doesn't contain any occurrance of it, probably because the covered time frame was too small - 1 hour or so.
If the maven-debug preset is still active, there should be a lot of maven-debug logs for quite a longer time frame covered.

Could you please send me all of them?

Thank you!

Hi Sergey,

I will generate the log for you - we don't use the TC on regular basis for now. Hopefully will get to this tomorrow (other tasks ;-)).

Thanks Milan

Hi Sergey,

I sent you the log yesterday and I had time this morning. I made a clean TC installation and tested it for like 20 minutes. TC didn't find the new snapshot in maven repo. I changed the parameters

teamcity.maven.artifactTrigger.checkInterval=60
teamcity.maven.artifactTrigger.timeToCache=0

in the internal.properties file and now it works like a charm. No red warning stripes, TC finds new snapshot immediatelly.

Thanks Milan

Hi Milan,

Thank you for the big log. It helped me discover several problems, but none of them can cause red alerts. Do you still see them?

Hi Sergey,

I do see them still, however maybe I've found the potential cause for our case. To make it work I needed to change the cache setup - actually by the parameters I provided I disabled the cache at all (I believe). It started to work and I didn't see any red warning. Once I added more modules (undestand more maven modules and more dependencies), red warnings started to appear.

When cache is disabled, the communication between TC and maven repo is more intensive. One reason could be that maven repo is not able to process all requests (I don't think the number of requests is so high, but still I need to investigate the web server behind the repo) or TC doesn't deal correctly with this situation.

Hopefully I will get to the investigation next week. Will keep you informed.

Thanks Milan

Milan,

With the settings you provided you indeed disabled the cache. Could you please provide the exact error message and the stacktrace shown in the alert. Thank you!

Hi Sergey,

here it is:

Unable to check for Maven dependency updates: Couldn't find information about xxxxx:jar:1.1-SNAPSHOT:compile in any of the available repositories:
Repository central: xxxxx-1.1-SNAPSHOT.jar does not exist

jetbrains.buildServer.buildTriggers.BuildTriggerException: Unable to check for Maven dependency updates: Couldn't find information about xxxxxxxx:jar:1.1-SNAPSHOT:compile in any of the available repositories:
Repository central: File: xxxxxx-1.1-SNAPSHOT.jar does not exist
at jetbrains.buildServer.maven.trigger.MavenArtifactTriggerBase.makeTriggerException(MavenArtifactTriggerBase.java:158)
at jetbrains.buildServer.maven.trigger.MavenArtifactTriggerBase.processJobResults(MavenArtifactTriggerBase.java:142)
at jetbrains.buildServer.maven.trigger.MavenArtifactTriggerBase.triggerBuild(MavenArtifactTriggerBase.java:55)
at jetbrains.buildServer.serverSide.impl.BuildTriggersChecker.triggerBuilds(BuildTriggersChecker.java:21)
at jetbrains.buildServer.serverSide.impl.BuildServerRunner$4.doSomething(BuildServerRunner.java:1)
at jetbrains.buildServer.serverSide.impl.BuildServerRunner$BuildServerWorker.run(BuildServerRunner.java:19)
at java.lang.Thread.run(Thread.java:595)
Caused by: jetbrains.buildServer.maven.acd.DetectionException: Couldn't find information about xxxxxxx:jar:1.1-SNAPSHOT:compile in any of the available repositories:
Repository central: File: xxxxxxxxx-1.1-SNAPSHOT.jar does not exist
at jetbrains.buildServer.maven.acd.Checker.check(Checker.java:58)
at jetbrains.buildServer.maven.acd.MavenArtifactChangeDetectorImpl.doCheckForChanges(MavenArtifactChangeDetectorImpl.java:176)
at jetbrains.buildServer.maven.acd.MavenArtifactChangeDetectorImpl.checkForChanges(MavenArtifactChangeDetectorImpl.java:132)
at jetbrains.buildServer.maven.trigger.SnapshotsCheckJob.perform(SnapshotsCheckJob.java:84)
at jetbrains.buildServer.maven.trigger.MavenArtifactTriggerBase$1.run(MavenArtifactTriggerBase.java:171)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
... 1 more
Caused by: jetbrains.buildServer.maven.acd.DigestRetrievalException: Couldn't find information about xxxxxxx:1.1-SNAPSHOT:compile in any of the available repositories:
Repository central: File: xxxxxxx-1.1-SNAPSHOT.jar does not exist
at jetbrains.buildServer.maven.acd.WagonDigestRetriever.retrieveDigest(WagonDigestRetriever.java:97)
at jetbrains.buildServer.maven.acd.WagonDigestRetriever.retrieveDigest(WagonDigestRetriever.java:52)
at jetbrains.buildServer.maven.acd.Checker.check(Checker.java:32)
... 7 more

Milan, it would be great if you send me the log with this error.
The previous log desn't contain anything alike.

Thank you!

Hi Sergey,

I know what you mean, but this errors aren't logged. At least they aren't logged into the teamcity-maven.log. Even during gathering the log I sent you the same warnings appeared - but they were not logged.

Thanks Milan

Hm, that's strange. According to the code there should be a log record with the same error message "Couldn't find information about xxxxxxx:1.1-SNAPSHOT ..." with a different exception class though. Did you try finding the textual message, not the class name?

Milan,

Could you please apply these new jars attached. They may fix the problems appearing as red warnings.

Thank you!

Hi,

I'm encountering the same problems that Milan was initially encountering (ie: the retrieved digest SHA-1 are not the latest in my snapshot repository for a particular snapshot artifact).  I have read through the entire thread and have seen several recommendations and new jars/etc to try.  Can you please let me what the current state is for this issue?  Which jars need to be replaced, which settings need to be updated, etc?  There seems to have been a lot of trial and error in this thread and am not sure exactly what needs to be done.

Secondly, will all these "patches" that must be applied be applied to the next release, or is this something that must be done manually every time?

Thanks,

Eric

Hi Eric,

First of all try disabling the cache. Add line

teamcity.maven.artifactTrigger.timeToCache=0

to the file <TC data dir>/config/internal.properties and restart the server. This helped Milan to fight the problem.

It would be better if you also apply the jars attached to one of the recent messages in the thread. They contain the fix for some concurrency issues. Just replace the existing jars with these.


Please let me know the results.

Thank you!

Hi Sergey,

I disabled the cache using a system property setting actually (avoids me modifying internal property files) so that when I upgrade TC next time I don't need to worry about overwriting some existing values.  Just doing that caused the same concurrency "red errors" that Milan was encountering.

I have since replaced the two maven jars with the ones that you supplied and the concurrency errors seem to have disappeared.

So overall, this is good news.  However, I have these following issues that remain.
1) Will these updated maven jars become part of the standard TC releases, or will I need to replace them everytime I upgrade TC?
2) I have disabled TC's caching of artifacts completely.  This will put an additional load on my Maven repo as it needs to check every time.  Will this bug be addressed as well in a subsequent release?

Thanks for the information.

Eric

Hi Eric,

> 1) Will these updated maven jars become part of the standard TC releases, or will I need to replace them everytime I upgrade TC?

They will. They are already in both 6.5.x and 7.0 branches.

> 2) I have disabled TC's caching of artifacts completely.  This will put an additional load on my Maven repo as it needs to check every time.  Will this bug be addressed as well in a subsequent release?

I hope it will be addressed. The problem is that I failed to reproduce it locally. If you were so kind and provide me with debug logs when the cache is enabled it would help me to fix it. :)

Hi Sergey,

Can you please let me know what debug settings you need?  Currently have the following in my teamcity-log4j-server.xml settings:

   <category name="jetbrains.buildServer.maven">
    <priority value="DEBUG"/>
    <appender-ref ref="ROLL"/>
  </category>

That's not enough, Eric.

Could you please do the following


1. Enable digest cache and set expiration time to some short value, say 60 seconds (teamcity.maven.artifactTrigger.timeToCache=60)
2. Put the attached debug-maven.xml to <TC data dir>/config/_logging
3. In Administration | Server Configuration | Diagnostics press on "Active logging preset" dropdown and select "debug-maven"

The file <TC dir>/logs/teamcity-maven.log should appear shortly

4. Update a dependency and let TeamCity work for several minutes.

Send me the log. Don't forget to specify when and which artifact you have updated.

Thank you for your help!

Hi Sergey,

I have gotten pulled onto something a little more urgent at the moment.  I will send you this information as soon as I have a moment.

Thanks,

Eric

Hi all,

I was able to reproduce the problem and fixed it. The fix will be available in 6.5.4.

Thank you all.