[JENKINS-38817] Processing is stuck during several operation

Type: Bug
Resolution: Won't Fix
Priority: Critical
Component/s: node-sharing-plugin
Labels:
None

Similar Issues:
Powered by SuggestiMate

Show

There are several operations (like create a new job, save/update computer configuration etc.) when the Jenkins master is stuck. The culprit is definitely foreman-node-sharing-plugin because if I un-install it, everything works like a charm. It looks the processing is somehow locked and stuck during the communication between Jenkins master and Foreman server.

Typical stacktrace for saving computer configuration:

Result: "Handling POST /hudson/computer/mswindows-win2k12_x86_64/configSubmit from 10.40.3.96 : ajp-127.0.0.1-8009-11" #2702 daemon prio=5
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
	- locked <0x54a0ef05> (a java.io.BufferedInputStream)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:709)
	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1220)
	- locked <0x4af7e79d> (a sun.net.www.protocol.http.HttpURLConnection)
	at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
	at org.glassfish.jersey.client.internal.HttpUrlConnector._apply(HttpUrlConnector.java:394)
	at org.glassfish.jersey.client.internal.HttpUrlConnector.apply(HttpUrlConnector.java:285)
	at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:255)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:684)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:681)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
	at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:681)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:411)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:311)
	at com.redhat.foreman.ForemanAPI.getForemanResponse(ForemanAPI.java:154)
	at com.redhat.foreman.ForemanAPI.getHostParameterValue(ForemanAPI.java:196)
	at com.redhat.foreman.ForemanAPI.getHostForQuery(ForemanAPI.java:313)
	at com.redhat.foreman.ForemanAPI.getCompatibleHosts(ForemanAPI.java:331)
	at com.redhat.foreman.ForemanSharedNodeCloud.canProvision(ForemanSharedNodeCloud.java:158)
	at hudson.model.Label.getClouds(Label.java:227)
	at hudson.model.Label.isEmpty(Label.java:435)
	at jenkins.model.Jenkins.trimLabels(Jenkins.java:1725)
	at jenkins.model.Nodes$3.run(Nodes.java:170)
	at hudson.model.Queue._withLock(Queue.java:1289)
	at hudson.model.Queue.withLock(Queue.java:1172)
	at jenkins.model.Nodes.removeNode(Nodes.java:160)
	at jenkins.model.Jenkins.removeNode(Jenkins.java:1700)
	at hudson.slaves.AbstractCloudSlave.terminate(AbstractCloudSlave.java:70)
	at com.redhat.foreman.ForemanSharedNode.terminate(ForemanSharedNode.java:32)
	at hudson.slaves.CloudRetentionStrategy.check(CloudRetentionStrategy.java:62)
	at hudson.slaves.CloudRetentionStrategy.check(CloudRetentionStrategy.java:46)
	at hudson.slaves.SlaveComputer$4.run(SlaveComputer.java:700)
	at hudson.model.Queue._withLock(Queue.java:1289)
	at hudson.model.Queue.withLock(Queue.java:1172)
	at hudson.slaves.SlaveComputer.setNode(SlaveComputer.java:697)
	at hudson.model.AbstractCIBase.updateComputer(AbstractCIBase.java:117)
	at hudson.model.AbstractCIBase.access$000(AbstractCIBase.java:44)
	at hudson.model.AbstractCIBase$2.run(AbstractCIBase.java:185)
	at hudson.model.Queue._withLock(Queue.java:1289)
	at hudson.model.Queue.withLock(Queue.java:1172)
	at hudson.model.AbstractCIBase.updateComputerList(AbstractCIBase.java:168)
	at jenkins.model.Jenkins.updateComputerList(Jenkins.java:1219)
	at jenkins.model.Nodes$1.run(Nodes.java:115)
	at hudson.model.Queue._withLock(Queue.java:1289)
	at hudson.model.Queue.withLock(Queue.java:1172)
	at jenkins.model.Nodes.setNodes(Nodes.java:105)
	at jenkins.model.Jenkins.setNodes(Jenkins.java:1704)
	at hudson.model.Computer.replaceBy(Computer.java:1405)
	- locked <0x71ffc733> (a hudson.model.Hudson)
	at hudson.model.Computer.doConfigSubmit(Computer.java:1355)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.kohsuke.stapler.Function$InstanceFunction.invoke(Function.java:298)
	at org.kohsuke.stapler.interceptor.RequirePOST$Processor.invoke(RequirePOST.java:46)
	at org.kohsuke.stapler.Function$InterceptedFunction.invoke(Function.java:399)
	at org.kohsuke.stapler.Function.bindAndInvoke(Function.java:161)
	at org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:96)
	at org.kohsuke.stapler.MetaClass$1.doDispatch(MetaClass.java:121)
	at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
	at org.kohsuke.stapler.MetaClass$13.dispatch(MetaClass.java:411)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
	at org.kohsuke.stapler.MetaClass$4.doDispatch(MetaClass.java:211)
	at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
	at org.kohsuke.stapler.Stapler.service(Stapler.java:238)
	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.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:123)
	at hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:95)
	at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:120)
	at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:114)
	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 org.jenkinsci.plugins.reverse_proxy_auth.ReverseProxySecurityRealm$1.doFilter(ReverseProxySecurityRealm.java:143)
	at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:168)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
	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:235)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:534)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
	at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:437)
	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:385)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
	at java.lang.Thread.run(Thread.java:682)

   Locked ownable synchronizers:
	- <0x78401481> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

Typical stracktrace for creating a new job:

"Handling GET /hudson/job/test-flow/configure from 10.40.3.131 : ajp-127.0.0.1-8009-11 Job/configure.jelly BuildFlow/configure-entries.jelly AbstractProject/configure-common.jelly" #2702 daemon prio=5
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
	- locked <0x1703bd47> (a java.io.BufferedInputStream)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:709)
	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1220)
	- locked <0x2fc84259> (a sun.net.www.protocol.http.HttpURLConnection)
	at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
	at org.glassfish.jersey.client.internal.HttpUrlConnector._apply(HttpUrlConnector.java:394)
	at org.glassfish.jersey.client.internal.HttpUrlConnector.apply(HttpUrlConnector.java:285)
	at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:255)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:684)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:681)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
	at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:681)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:411)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:311)
	at com.redhat.foreman.ForemanAPI.getForemanResponse(ForemanAPI.java:154)
	at com.redhat.foreman.ForemanAPI.getHostParameterValue(ForemanAPI.java:196)
	at com.redhat.foreman.ForemanAPI.getHostForQuery(ForemanAPI.java:313)
	at com.redhat.foreman.ForemanAPI.getCompatibleHosts(ForemanAPI.java:331)
	at com.redhat.foreman.ForemanSharedNodeCloud.canProvision(ForemanSharedNodeCloud.java:158)
	at hudson.model.Label.getClouds(Label.java:227)
	at hudson.model.Label.isEmpty(Label.java:435)
	at jenkins.model.Jenkins.getLabels(Jenkins.java:1614)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.commons.jexl.util.PropertyExecutor.execute(PropertyExecutor.java:125)
	at org.apache.commons.jexl.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:314)
	at org.apache.commons.jexl.parser.ASTArrayAccess.evaluateExpr(ASTArrayAccess.java:185)
	at org.apache.commons.jexl.parser.ASTIdentifier.execute(ASTIdentifier.java:75)
	at org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
	at org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
	at org.apache.commons.jexl.parser.ASTGTNode.value(ASTGTNode.java:62)
	at org.apache.commons.jexl.parser.ASTOrNode.value(ASTOrNode.java:55)
	at org.apache.commons.jexl.parser.ASTOrNode.value(ASTOrNode.java:55)
	at org.apache.commons.jexl.parser.ASTExpression.value(ASTExpression.java:54)
	at org.apache.commons.jexl.parser.ASTExpressionExpression.value(ASTExpressionExpression.java:56)
	at org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
	at hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:74)
	at org.apache.commons.jelly.expression.ExpressionSupport.evaluateRecurse(ExpressionSupport.java:61)
	at org.apache.commons.jelly.expression.ExpressionSupport.evaluateAsBoolean(ExpressionSupport.java:71)
	at org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:97)
	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.IncludeTag.doTag(IncludeTag.java:147)
	at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
	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.IncludeTag.doTag(IncludeTag.java:147)
	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.CallTagLibScript$1.run(CallTagLibScript.java:99)
	at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
	at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
	at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
	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.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
	at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
	at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
	at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
	at org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
	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.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
	at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
	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.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.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.JellyFacet$1.dispatch(JellyFacet.java:95)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
	at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:249)
	at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
	at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
	at org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
	at org.kohsuke.stapler.Stapler.service(Stapler.java:238)
	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.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:123)
	at hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:95)
	at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:120)
	at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:114)
	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 org.jenkinsci.plugins.reverse_proxy_auth.ReverseProxySecurityRealm$1.doFilter(ReverseProxySecurityRealm.java:143)
	at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:168)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
	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:235)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:534)
	at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
	at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
	at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:437)
	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:385)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
	at java.lang.Thread.run(Thread.java:682)

In the same time there is usually at least one (I haven't see more that 4 yet) timer threads which utilize Foreman as well with stacktrace like:

"jenkins.util.Timer [#10]" #368 daemon prio=5
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
	- locked <0x61eaba62> (a java.io.BufferedInputStream)
	at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:709)
	at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1220)
	- locked <0x5700e314> (a sun.net.www.protocol.http.HttpURLConnection)
	at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:379)
	at org.glassfish.jersey.client.internal.HttpUrlConnector._apply(HttpUrlConnector.java:394)
	at org.glassfish.jersey.client.internal.HttpUrlConnector.apply(HttpUrlConnector.java:285)
	at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:255)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:684)
	at org.glassfish.jersey.client.JerseyInvocation$1.call(JerseyInvocation.java:681)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
	at org.glassfish.jersey.internal.Errors.process(Errors.java:228)
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:444)
	at org.glassfish.jersey.client.JerseyInvocation.invoke(JerseyInvocation.java:681)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.method(JerseyInvocation.java:411)
	at org.glassfish.jersey.client.JerseyInvocation$Builder.get(JerseyInvocation.java:311)
	at com.redhat.foreman.ForemanAPI.getForemanResponse(ForemanAPI.java:154)
	at com.redhat.foreman.ForemanAPI.getHostParameterValue(ForemanAPI.java:196)
	at com.redhat.foreman.ForemanAPI.getHostForQuery(ForemanAPI.java:313)
	at com.redhat.foreman.ForemanAPI.getCompatibleHosts(ForemanAPI.java:331)
	at com.redhat.foreman.ForemanSharedNodeCloud.canProvision(ForemanSharedNodeCloud.java:158)
	at hudson.slaves.NodeProvisioner$StandardStrategyImpl.apply(NodeProvisioner.java:661)
	at hudson.slaves.NodeProvisioner.update(NodeProvisioner.java:286)
	at hudson.slaves.NodeProvisioner.access$000(NodeProvisioner.java:57)
	at hudson.slaves.NodeProvisioner$NodeProvisionerInvoker.doRun(NodeProvisioner.java:775)
	at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:51)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
	at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
	at java.lang.Thread.run(Thread.java:682)

   Locked ownable synchronizers:
	- <0x6f6519f6> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	- <0x568b9e9c> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

If I save only one computer cfg. it takes let say several minutes, but usually finally proceed, but if I save 2 or more computers in parallel and/or create a new job in the same time, I'm pretty sure I'll get an error message (HTTP 500) and such a (above) thread(s) is is alive for couple of hours.

I have no idea why the processing is stuck in a receiving data from Foreman instance there is no reason why a request to Foreman can take several minutes for reponse , but on my Jenkins deployment it can be demonstrated quite easily.

In addition, I've tried in the same time Test connection on cfg. page several times and the response was up to 5s!

The issue can be improved a bit when ~~JENKINS-38815~~ is resolved, but that only hides the root (unknown yet) cause.

is related to

JENKINS-38815 ForemanSharedNodeCloud.canProvision(...) has to use a caching mechanism

Resolved

Pavel Janoušek added a comment - 2016-10-07 13:01

Based on my deeper investigation and time spent measurement, I found (hopefully) the root cause. The issue is obviously related to efficiency of overloaded ForemanSharedNodeCloud.canProvision() method which should be as mush as we can quick. It is invoked really many times, currently in small Jenkins master deployment I've got 10 thread instances of jenkins.util.Timer and above 100 thread instances of Computer.threadPoolForRemoting, right after 14 minutes from Jenkins master booting. Each response from Foreman instance takes ~0.2-2s. According current impl. of ForemanAPI.getCompatibleHosts() it takes at least 1 request for the list of hosts with the appropriate parameters plus one request for each defined node... so ForemanSharedNodeCloud.canProvision() takes approx. 5+ seconds for each such request if we have around 5 nodes defined. As I already stated, many of such requests are done after either Jenkins Model or Queue is locked and in that case many thread can start starving. This is exactly what happened to processed configSubmit (save slave cfg.). We can't bypass such Jenkins locking mechanism, but we have to be as much as we can effective. Locking queue or model for couple of seconds is simply killer even for small Jenkins deployment.

I'd propose to resolve ~~JENKINS-38815~~ first and this issue probably vanishes.

Pavel Janoušek added a comment - 2016-10-07 13:01 Based on my deeper investigation and time spent measurement, I found (hopefully) the root cause. The issue is obviously related to efficiency of overloaded ForemanSharedNodeCloud.canProvision() method which should be as mush as we can quick . It is invoked really many times, currently in small Jenkins master deployment I've got 10 thread instances of jenkins.util.Timer and above 100 thread instances of Computer.threadPoolForRemoting , right after 14 minutes from Jenkins master booting. Each response from Foreman instance takes ~0.2-2s. According current impl. of ForemanAPI.getCompatibleHosts() it takes at least 1 request for the list of hosts with the appropriate parameters plus one request for each defined node... so ForemanSharedNodeCloud.canProvision() takes approx. 5+ seconds for each such request if we have around 5 nodes defined. As I already stated, many of such requests are done after either Jenkins Model or Queue is locked and in that case many thread can start starving. This is exactly what happened to processed configSubmit (save slave cfg.). We can't bypass such Jenkins locking mechanism, but we have to be as much as we can effective. Locking queue or model for couple of seconds is simply killer even for small Jenkins deployment. I'd propose to resolve JENKINS-38815 first and this issue probably vanishes.

Pavel Janoušek added a comment - 2016-10-31 09:38

It seems issue is fixed by ~~JENKINS-38815~~ already.

Pavel Janoušek added a comment - 2016-10-31 09:38 It seems issue is fixed by JENKINS-38815 already.

Details

Description

Attachments

Issue Links

Activity

Collapse comment: Pavel Janoušek added a comment - 2016-10-07 13:01

Expand comment: Pavel Janoušek added a comment - 2016-10-07 13:01

Collapse comment: Pavel Janoušek added a comment - 2016-10-31 09:38

Expand comment: Pavel Janoušek added a comment - 2016-10-31 09:38

People

Dates