The Jenkins Plugin Developer case files: Episode 1 - When @Extensions bites you in the posterior
Before I forget, if you have the Metrics plugin installed, please update to 3.0.7 or newer
Metrics Plugin 3.0.7 http://t.co/myh5yRfevz #cloudbees #JenkinsEnterprise #JenkinsMetrics
— JE Plugin Releases (@jepluginrelease) October 3, 2014
So Jenkins has this extremely useful extension mechanism. It is part of what makes Jenkins so easy to extend. You create a type, have it extend ExtensionPoint (or be even more fancy with a Describable - Descriptor pair of classes) and other plugins can register their extensions by extending your class and annotating with @Extension
A common thing to want to do then, is pick up all the extensions. If we take the Metrics plugin, it has a class
public abstract class MetricProvider implements ExtensionPoint {...}
And unsurprisingly, one of the first things we want to do is register all the metrics provided by the providers.
You might naïvely think that a good place to do this would be in Plugin.start() which gets called when the plugin is started.
The problem is that the extensions list is still mutable at that point because not all plugins have been initialized yet and thus you may not have all the extensions available.
So next you move on to Plugin.postInitialze() which gets called when all plugins have been started.
Have a look at the JavaDoc for Plugin.postInitialize()
/**
* Called after {@link #start()} is called for all the plugins.
*
* @throws Exception
* any exception thrown by the plugin during the initialization will disable plugin.
*/
public void postInitialize() throws Exception {}
So any exception thrown will disable the plugin… thus the extension list is still mutable at that point in time… if there are any other plugins doing the same or similar then you can end up in a deadlock such as this:
"Handling GET /adjuncts/5e27f651/org/kohsuke/stapler/bind.js : http-8091-4 HudsonIsLoading/index.jelly": at hudson.ExtensionList.ensureLoaded(ExtensionList.java:247) - waiting to lock (a hudson.ExtensionList$Lock) at hudson.ExtensionList.getComponents(ExtensionList.java:149) at hudson.DescriptorExtensionList.load(DescriptorExtensionList.java:182) at hudson.ExtensionList.ensureLoaded(ExtensionList.java:248) - locked (a hudson.DescriptorExtensionList) at hudson.ExtensionList.iterator(ExtensionList.java:138) at org.apache.commons.jelly.expression.ExpressionSupport.evaluateAsIterator(ExpressionSupport.java:101) at org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:89) at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105) at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105) at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95) at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63) at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53) at org.kohsuke.stapler.jelly.JellyRequestDispatcher.forward(JellyRequestDispatcher.java:55) at hudson.util.HudsonIsLoading.doDynamic(HudsonIsLoading.java:45) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.kohsuke.stapler.Function$InstanceFunction.invoke(Function.java:298) at org.kohsuke.stapler.Function.bindAndInvoke(Function.java:161) at org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:96) at org.kohsuke.stapler.MetaClass$11.dispatch(MetaClass.java:370) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:733) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:863) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:636) at org.kohsuke.stapler.Stapler.service(Stapler.java:225) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.ResponseHeaderFilter.doFilter(ResponseHeaderFilter.java:100) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:96) at hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:58) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at jenkins.metrics.impl.MetricsFilter.doFilter(MetricsFilter.java:117) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at org.jvnet.hudson.plugins.cors.JenkinsCorsFilter.doFilter(JenkinsCorsFilter.java:42) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:88) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:48) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:162) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:470) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:554) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) at java.lang.Thread.run(Unknown Source) "Initializing plugin metrics": at hudson.ExtensionList.ensureLoaded(ExtensionList.java:247) - waiting to lock (a hudson.DescriptorExtensionList) at hudson.ExtensionList.iterator(ExtensionList.java:138) at hudson.model.User.load(User.java:151) - locked (a hudson.model.User) at hudson.model.User.(User.java:122) at hudson.model.User.getOrCreate(User.java:346) at hudson.model.User.current(User.java:384) at hudson.plugins.jobConfigHistory.PluginUtils.getHistoryDao(PluginUtils.java:78) at hudson.plugins.jobConfigHistory.PluginUtils.getHistoryDao(PluginUtils.java:62) at hudson.plugins.jobConfigHistory.JobConfigHistoryPurger.(JobConfigHistoryPurger.java:48) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source) at java.lang.reflect.Constructor.newInstance(Unknown Source) at com.google.inject.internal.DefaultConstructionProxyFactory$1.newInstance(DefaultConstructionProxyFactory.java:86) at com.google.inject.internal.ConstructorInjector.provision(ConstructorInjector.java:108) at com.google.inject.internal.ConstructorInjector.construct(ConstructorInjector.java:88) at com.google.inject.internal.ConstructorBindingImpl$Factory.get(ConstructorBindingImpl.java:269) at com.google.inject.internal.ProviderToInternalFactoryAdapter$1.call(ProviderToInternalFactoryAdapter.java:46) at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1058) at com.google.inject.internal.ProviderToInternalFactoryAdapter.get(ProviderToInternalFactoryAdapter.java:40) at com.google.inject.Scopes$1$1.get(Scopes.java:65) - locked (a java.lang.Class for com.google.inject.internal.InternalInjectorCreator) at hudson.ExtensionFinder$GuiceFinder$FaultTolerantScope$1.get(ExtensionFinder.java:429) at com.google.inject.internal.InternalFactoryToProviderAdapter.get(InternalFactoryToProviderAdapter.java:41) at com.google.inject.internal.InjectorImpl$3$1.call(InjectorImpl.java:1005) at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1051) at com.google.inject.internal.InjectorImpl$3.get(InjectorImpl.java:1001) at hudson.ExtensionFinder$GuiceFinder._find(ExtensionFinder.java:391) at hudson.ExtensionFinder$GuiceFinder.find(ExtensionFinder.java:382) at hudson.ExtensionFinder._find(ExtensionFinder.java:151) at hudson.ClassicPluginStrategy.findComponents(ClassicPluginStrategy.java:316) at hudson.ExtensionList.load(ExtensionList.java:295) at hudson.ExtensionList.ensureLoaded(ExtensionList.java:248) - locked (a hudson.ExtensionList$Lock) at hudson.ExtensionList.iterator(ExtensionList.java:138) at hudson.ExtensionList.get(ExtensionList.java:129) at jenkins.metrics.api.Metrics$HeathCheckMetricsProvider.getMetricSet(Metrics.java:322) at jenkins.metrics.api.Metrics.postInitialize(Metrics.java:287) at hudson.PluginManager$2$1$2.run(PluginManager.java:376) at org.jvnet.hudson.reactor.TaskGraphBuilder$TaskImpl.run(TaskGraphBuilder.java:169) at org.jvnet.hudson.reactor.Reactor.runTask(Reactor.java:282) at jenkins.model.Jenkins$7.runTask(Jenkins.java:899) at org.jvnet.hudson.reactor.Reactor$2.run(Reactor.java:210) at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) "http-8091-1": at hudson.ExtensionList.ensureLoaded(ExtensionList.java:247) - waiting to lock (a hudson.ExtensionList$Lock) at hudson.ExtensionList.getComponents(ExtensionList.java:149) at hudson.DescriptorExtensionList.load(DescriptorExtensionList.java:182) at hudson.ExtensionList.ensureLoaded(ExtensionList.java:248) - locked (a hudson.DescriptorExtensionList) at hudson.ExtensionList.iterator(ExtensionList.java:138) at hudson.model.User.load(User.java:151) - locked (a hudson.model.User) at hudson.model.User.(User.java:122) at hudson.model.User.getOrCreate(User.java:346) at hudson.model.User.getAll(User.java:406) at hudson.model.User$FullNameIdResolver.resolveCanonicalId(User.java:768) at hudson.model.User.get(User.java:327) at hudson.model.User.get(User.java:300) at jenkins.model.Jenkins.getUser(Jenkins.java:2390) at hudson.plugins.greenballs.GreenBallFilter.mapImage(GreenBallFilter.java:64) at hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:47) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at jenkins.metrics.impl.MetricsFilter.doFilter(MetricsFilter.java:117) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at org.jvnet.hudson.plugins.cors.JenkinsCorsFilter.doFilter(JenkinsCorsFilter.java:42) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:88) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:48) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:162) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:470) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:554) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) at java.lang.Thread.run(Unknown Source)
So what is going on in the above deadlock?
The “please wait…” page needs a list of all extensions in order to ensure that the page is correctly decorated during startup.
The metrics plugin was querying the list of extensions in order to register all the metrics providers.
This forces Jenkins to complete the initialization of all extensions.
Thus the Job Config History plugin needs to be initialized.
As part of that plugins initialization, it needs to know the current user . As part of the loading of the current user, Jenkins needs to query the extension list of UserPropertyDescriptors .
The GreenBalls plugin needs to know if the current user has enabled greenballs… so it asks Jenkins for the current user
Jenkins then needs to resolve the current user and ends up loading the user record. As part of the loading of the current user, Jenkins needs to query the extension list of UserPropertyDescriptors .
We have a confluence of three things all hitting at the same time:
A perfectly timed HTTP request for the root page
The metrics plugin forcing the initialization of all extension points
Another perfectly timed HTTP request
All three are fighting for three different locks in different orders.
So what should be fixed?
The greenballs plugin should have it’s filter perform a no-op until after Jenkins passes the InitMilestone.EXTENSIONS_AUGMENTED point in the lifecycle… after all there will be no balls displayed prior to this point in time
The jobConfigHistory plugin should not be decorating the page with a list of the changes that the current user has made until Jenkins passes the InitMilestone.EXTENSIONS_AUGMENTED point in the lifecycle… because there is no way that the current user could have made any changes until after InitMilestone.COMPLETED . Note that the jobConfigHistory plugin does need to inject its tentacles early though as it will want to catch configuration changes made by Jenkins during initialization… but those can safely be attributed to Jenkins itself and not any specific user.
The metrics plugin should not enumerate extensions until it is safe to do so . (DONE… upgrade to 3.0.7 or newer to get the fix)
Lessons learned
Be careful when using Jenkins Extension mechanism in order to ensure that you are looking up the extensions only after it is safe to do so, IOW after InitMilestone.EXTENSIONS_AUGMENTED . Calling Jenkins.getInstance.getExtensionList(…) prior to that point in the Jenkins lifecycle will only give rise to the risk of deadlock
Stephen Connolly
Elite Developer and Architect
CloudBees
Stay up to date
We'll never share your email address and you can opt out at any time, we promise.