and build. The /job/flow/1/flowGraphTable/ will show, say, Install a tool running, and /job/flow/1/execution/node/6/log/ will have some output (/job/flow/1/execution/node/5/log/ will too). Yet /job/flow/1/console ends with Running: Allocate node : Body : Start and does not show this output until later, when the sh step is running.
Subsequent builds do not show this problem, even if sh 'sleep 5' steps are interjected to make them run more slowly—unless the tool cache and workspace are deleted and previous builds are deleted, in which case it happens again.
The second, but not the first, time this happened I saw in the logs something which is probably unrelated:
Dec 02, 2014 3:21:15 PM org.jenkinsci.plugins.workflow.graph.FlowNode$1 persist
WARNING: failed to save actions for FlowNode id=3
java.io.IOException: Unable to delete .../jobs/flow/builds/2014-12-02_15-21-15/workflow/3.xml
at hudson.util.AtomicFileWriter.commit(AtomicFileWriter.java:112)
at hudson.XmlFile.write(XmlFile.java:179)
at org.jenkinsci.plugins.workflow.support.storage.SimpleXStreamFlowNodeStorage.saveActions(SimpleXStreamFlowNodeStorage.java:106)
at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.saveActions(CpsFlowExecution.java:640)
at org.jenkinsci.plugins.workflow.graph.FlowNode.save(FlowNode.java:254)
at org.jenkinsci.plugins.workflow.graph.FlowNode$1.persist(FlowNode.java:241)
at org.jenkinsci.plugins.workflow.graph.FlowNode$1.add(FlowNode.java:217)
at org.jenkinsci.plugins.workflow.graph.FlowNode$1.add(FlowNode.java:208)
at java.util.AbstractList.add(AbstractList.java:108)
at hudson.model.Actionable.addAction(Actionable.java:122)
at org.jenkinsci.plugins.workflow.support.steps.ExecutorStepExecution$PlaceholderTask$PlaceholderExecutable.run(ExecutorStepExecution.java:403)
at hudson.model.ResourceController.execute(ResourceController.java:89)
at hudson.model.Executor.run(Executor.java:240)
Thread dumps suggest that ToolStep is to blame:
"Computer.threadPoolForRemoting [#9]" #202 daemon prio=5 os_prio=0 tid=0x00007f67e0005800 nid=0x544b runnable [0x00007f6821f8b000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
- locked <0x000000079bce0d98> (a java.net.SocksSocketImpl)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at java.net.Socket.connect(Socket.java:538)
at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
- locked <0x000000079bce0d10> (a sun.net.www.http.HttpClient)
at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)
at sun.net.www.http.HttpClient.New(HttpClient.java:308)
at sun.net.www.http.HttpClient.New(HttpClient.java:326)
at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1167)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1103)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:997)
at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:931)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1511)
- locked <0x000000079bce02c0> (a sun.net.www.protocol.http.HttpURLConnection)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1439)
- locked <0x000000079bce02c0> (a sun.net.www.protocol.http.HttpURLConnection)
at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2929)
at java.net.URLConnection.getHeaderFieldLong(URLConnection.java:629)
at java.net.URLConnection.getContentLengthLong(URLConnection.java:501)
at java.net.URLConnection.getContentLength(URLConnection.java:485)
at org.jvnet.robust_http_client.RetryableHttpStream.<init>(RetryableHttpStream.java:90)
at org.jvnet.robust_http_client.RetryableHttpStream.<init>(RetryableHttpStream.java:74)
at hudson.ProxyConfiguration.getInputStream(ProxyConfiguration.java:246)
at hudson.FilePath.installIfNecessaryFrom(FilePath.java:808)
at hudson.tools.DownloadFromUrlInstaller.performInstallation(DownloadFromUrlInstaller.java:70)
at hudson.tools.InstallerTranslator.getToolHome(InstallerTranslator.java:68)
at hudson.tools.ToolLocationNodeProperty.getToolHome(ToolLocationNodeProperty.java:107)
at hudson.tools.ToolInstallation.translateFor(ToolInstallation.java:205)
at hudson.tasks.Maven$MavenInstallation.forNode(Maven.java:609)
at hudson.tasks.Maven$MavenInstallation.forNode(Maven.java:446)
at org.jenkinsci.plugins.workflow.steps.ToolStep$Execution.run(ToolStep.java:126)
at org.jenkinsci.plugins.workflow.steps.ToolStep$Execution.run(ToolStep.java:109)
at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousStepExecution.start(AbstractSynchronousStepExecution.java:34)
at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:137)
at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:98)
at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.call(PogoMetaClassSite.java:45)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:42)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
at com.cloudbees.groovy.cps.sandbox.DefaultInvoker.methodCall(DefaultInvoker.java:15)
at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:69)
at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:100)
at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:76)
at sun.reflect.GeneratedMethodAccessor208.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72)
at com.cloudbees.groovy.cps.impl.ConstantBlock.eval(ConstantBlock.java:21)
at com.cloudbees.groovy.cps.Next.step(Next.java:58)
at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:145)
at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:164)
at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.run(CpsThreadGroup.java:262)
at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.access$000(CpsThreadGroup.java:70)
at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:174)
at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:172)
at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$2.call(CpsVmExecutorService.java:47)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:111)
at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Perhaps it should in fact be an asynchronous step. We may need to introduce a convenience variant of AbstractSynchronousStepExecution for long-running, but not resumable, processes that can produce intermediate output and may honor Thread.interrupt.
(In this case DownloadFromUrlInstaller actually could handle Jenkins restarts, by writing the tool to a temporary location and then moving it atomically when done. Then the step could permit resumption by simply calling forNode again in the next session, since it should be idempotent.)
