Skip to content

Test cases for JENKINS-41854#70

Merged
dwnusbaum merged 4 commits into
jenkinsci:masterfrom
basil:JENKINS-41854
Aug 22, 2018
Merged

Test cases for JENKINS-41854#70
dwnusbaum merged 4 commits into
jenkinsci:masterfrom
basil:JENKINS-41854

Conversation

@basil

@basil basil commented May 22, 2018

Copy link
Copy Markdown
Member

Problem

JENKINS-41854 affects my production Jenkins servers at least once a month. My only recourse is to restart Jenkins, which rehydrates the FilePath as described in the bug. Between the time that I hit the bug and the time I restart Jenkins, in-use workspaces are handed out to new jobs, causing both jobs to fail. I provided a detailed write-up of my experiences in JENKINS-50504, which I have now marked as a duplicate of JENKINS-41854 (I didn't know about JENKINS-41854 at the time).

Solution

Work towards fixing the bug by writing a reproducible test case. This test case focuses on highlighting the two failure modes described in the bug:

  • If an agent is disconnected and reconnected during the first of two sh steps in a node, then the second sh step will fail.
  • If an agent is disconnected and reconnected, a fresh WorkspaceList lock needs to be acquired, after a new Computer becomes available and hence a new WorkspaceList.

Implementation

I found that the existing buildShellScriptAcrossDisconnect test could be extended to cover this bug, so I added some additional logic to it to demonstrate these two failure modes. I left the new logic commented out in places where it would currently cause the test to fail (until JENKINS-41854 is fixed). An alternative approach would have been to copy and paste the test into a new test, add the new logic there (without commenting it out), and skip the new test using @Ignore. Please let me know if you'd prefer that approach instead.

Testing

When the "Back again" line is uncommented, the test fails as described in the bug (and with the same exception I see on my production Jenkins server with real jobs):

   4.634 [demo #1] Started
   5.891 [demo #1] [Pipeline] node
   8.484 [demo #1] Running on dumbo in /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit5210374757619203863/workspace/demo
   8.485 [demo #1] [Pipeline] {
   9.915 [demo #1] [Pipeline] sh
  10.608 [demo #1] [demo] Running shell script
  10.608 [demo #1] Cannot contact dumbo: hudson.remoting.RequestAbortedException: java.nio.channels.ClosedChannelException
  12.344 [demo #1] + touch /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit6462864648634361788/junit5482144690654488963/f2
  12.345 [demo #1] + '[' -f /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit6462864648634361788/junit5482144690654488963/f1 ']'
  12.345 [demo #1] + sleep 1
  12.345 [demo #1] + '[' -f /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit6462864648634361788/junit5482144690654488963/f1 ']'
  12.345 [demo #1] + sleep 1
  12.346 [demo #1] + '[' -f /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit6462864648634361788/junit5482144690654488963/f1 ']'
  12.346 [demo #1] + echo finished waiting
  12.346 [demo #1] finished waiting
  12.346 [demo #1] + rm /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit6462864648634361788/junit5482144690654488963/f2
  12.347 [demo #1] [Pipeline] sh
  12.403 [demo #1] [Pipeline] }
  12.404 [demo #1] [Pipeline] // node
  12.412 [id=82]	INFO	o.j.p.workflow.job.WorkflowRun#finish: demo #1 completed: FAILURE
  12.425 [demo #1] [Pipeline] End of Pipeline
  12.425 [demo #1] java.io.IOException: remote file operation failed: /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit5210374757619203863/workspace/demo at hudson.remoting.Channel@595862ad:JNLP4-connect connection from localhost/127.0.0.1:50797: hudson.remoting.ChannelClosedException: channel is already closed
  12.425 [demo #1] 	at hudson.FilePath.act(FilePath.java:994)
  12.425 [demo #1] 	at hudson.FilePath.act(FilePath.java:976)
  12.425 [demo #1] 	at hudson.FilePath.mkdirs(FilePath.java:1159)
  12.426 [demo #1] 	at org.jenkinsci.plugins.durabletask.FileMonitoringTask$FileMonitoringController.<init>(FileMonitoringTask.java:115)
  12.426 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript$ShellController.<init>(BourneShellScript.java:198)
  12.426 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript$ShellController.<init>(BourneShellScript.java:190)
  12.426 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript.launchWithCookie(BourneShellScript.java:111)
  12.426 [demo #1] 	at org.jenkinsci.plugins.durabletask.FileMonitoringTask.launch(FileMonitoringTask.java:66)
  12.426 [demo #1] 	at org.jenkinsci.plugins.workflow.steps.durable_task.DurableTaskStep$Execution.start(DurableTaskStep.java:176)
  12.426 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.DSL.invokeStep(DSL.java:184)
  12.426 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:126)
  12.426 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:108)
  12.426 [demo #1] 	at groovy.lang.GroovyObject$invokeMethod.call(Unknown Source)
  12.426 [demo #1] 	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
  12.427 [demo #1] 	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
  12.427 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:151)
  12.427 [demo #1] 	at org.kohsuke.groovy.sandbox.GroovyInterceptor.onMethodCall(GroovyInterceptor.java:21)
  12.427 [demo #1] 	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxInterceptor.onMethodCall(SandboxInterceptor.java:115)
  12.427 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:149)
  12.427 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:146)
  12.427 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:123)
  12.429 [demo #1] 	at com.cloudbees.groovy.cps.sandbox.SandboxInvoker.methodCall(SandboxInvoker.java:16)
  12.430 [demo #1] 	at WorkflowScript.run(WorkflowScript:3)
  12.430 [demo #1] 	at ___cps.transform___(Native Method)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:48)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82)
  12.430 [demo #1] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  12.430 [demo #1] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  12.430 [demo #1] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  12.430 [demo #1] 	at java.lang.reflect.Method.invoke(Method.java:498)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.impl.ConstantBlock.eval(ConstantBlock.java:21)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.Next.step(Next.java:58)
  12.430 [demo #1] 	at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:154)
  12.431 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.access$001(SandboxContinuable.java:18)
  12.431 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:33)
  12.431 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:30)
  12.431 [demo #1] 	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.GroovySandbox.runInSandbox(GroovySandbox.java:108)
  12.431 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.run0(SandboxContinuable.java:30)
  12.431 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:163)
  12.432 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.run(CpsThreadGroup.java:324)
  12.432 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.access$100(CpsThreadGroup.java:78)
  12.432 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:236)
  12.432 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:224)
  12.432 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$2.call(CpsVmExecutorService.java:63)
  12.432 [demo #1] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  12.432 [demo #1] 	at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
  12.432 [demo #1] 	at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
  12.432 [demo #1] 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
  12.433 [demo #1] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  12.433 [demo #1] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  12.433 [demo #1] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  12.433 [demo #1] 	at java.lang.Thread.run(Thread.java:745)
  12.433 [demo #1] Caused by: hudson.remoting.ChannelClosedException: channel is already closed
  12.433 [demo #1] 	at hudson.remoting.Channel.send(Channel.java:605)
  12.433 [demo #1] 	at hudson.remoting.Request.call(Request.java:130)
  12.434 [demo #1] 	at hudson.remoting.Channel.call(Channel.java:829)
  12.434 [demo #1] 	at hudson.FilePath.act(FilePath.java:987)
  12.434 [demo #1] 	at hudson.FilePath.act(FilePath.java:976)
  12.434 [demo #1] 	at hudson.FilePath.mkdirs(FilePath.java:1159)
  12.434 [demo #1] 	at org.jenkinsci.plugins.durabletask.FileMonitoringTask$FileMonitoringController.<init>(FileMonitoringTask.java:115)
  12.434 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript$ShellController.<init>(BourneShellScript.java:198)
  12.434 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript$ShellController.<init>(BourneShellScript.java:190)
  12.434 [demo #1] 	at org.jenkinsci.plugins.durabletask.BourneShellScript.launchWithCookie(BourneShellScript.java:111)
  12.434 [demo #1] 	at org.jenkinsci.plugins.durabletask.FileMonitoringTask.launch(FileMonitoringTask.java:66)
  12.434 [demo #1] 	at org.jenkinsci.plugins.workflow.steps.durable_task.DurableTaskStep$Execution.start(DurableTaskStep.java:176)
  12.434 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.DSL.invokeStep(DSL.java:184)
  12.435 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:126)
  12.435 [demo #1] 	at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:108)
  12.435 [demo #1] 	at groovy.lang.GroovyObject$invokeMethod.call(Unknown Source)
  12.435 [demo #1] 	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
  12.435 [demo #1] 	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
  12.435 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:151)
  12.435 [demo #1] 	at org.kohsuke.groovy.sandbox.GroovyInterceptor.onMethodCall(GroovyInterceptor.java:21)
  12.435 [demo #1] 	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxInterceptor.onMethodCall(SandboxInterceptor.java:115)
  12.435 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker$1.call(Checker.java:149)
  12.435 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:146)
  12.435 [demo #1] 	at org.kohsuke.groovy.sandbox.impl.Checker.checkedCall(Checker.java:123)
  12.435 [demo #1] 	at com.cloudbees.groovy.cps.sandbox.SandboxInvoker.methodCall(SandboxInvoker.java:16)
  12.436 [demo #1] 	... 30 more
  12.436 [demo #1] Caused by: java.nio.channels.ClosedChannelException
  12.436 [demo #1] 	at org.jenkinsci.remoting.protocol.NetworkLayer.onRecvClosed(NetworkLayer.java:154)
  12.436 [demo #1] 	at org.jenkinsci.remoting.protocol.impl.NIONetworkLayer.ready(NIONetworkLayer.java:142)
  12.436 [demo #1] 	at org.jenkinsci.remoting.protocol.IOHub$OnReady.run(IOHub.java:721)
  12.436 [demo #1] 	at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
  12.436 [demo #1] 	... 3 more
  12.436 [demo #1] Finished: FAILURE

When the second assertWorkspaceLocked is uncommented (even if the "Back again" line is still commented out), the test also fails as described in the bug because a fresh WorkspaceList lock was not acquired and the [still in-use] workspace is handed out again:

java.lang.AssertionError: Values should be different. Actual: /var/folders/sd/c1y1b1c542z88kn6k7drmq2h0000gq/T/junit5215775594896445420/workspace/demo

	at org.junit.Assert.fail(Assert.java:88)
	at org.junit.Assert.failEquals(Assert.java:185)
	at org.junit.Assert.assertNotEquals(Assert.java:161)
	at org.junit.Assert.assertNotEquals(Assert.java:175)
	at org.jenkinsci.plugins.workflow.support.steps.ExecutorStepTest.assertWorkspaceLocked(ExecutorStepTest.java:351)
	at org.jenkinsci.plugins.workflow.support.steps.ExecutorStepTest.access$100(ExecutorStepTest.java:111)
	at org.jenkinsci.plugins.workflow.support.steps.ExecutorStepTest$6.evaluate(ExecutorStepTest.java:331)
	at org.jvnet.hudson.test.RestartableJenkinsRule$4.evaluate(RestartableJenkinsRule.java:110)
	at org.jvnet.hudson.test.JenkinsRule$1.evaluate(JenkinsRule.java:548)
	at org.jvnet.hudson.test.RestartableJenkinsRule.run(RestartableJenkinsRule.java:126)
	at org.jvnet.hudson.test.RestartableJenkinsRule.access$100(RestartableJenkinsRule.java:31)
	at org.jvnet.hudson.test.RestartableJenkinsRule$1.evaluate(RestartableJenkinsRule.java:65)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)

@basil

basil commented May 22, 2018

Copy link
Copy Markdown
Member Author

@jglick Please let me know how else I can help to get this bug fixed.

@jglick
jglick requested review from abayer, rsandell and svanoort June 5, 2018 23:22
});
}

@Issue("JENKINS-41854")

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Rather write a new test case, and mark it

@Ignore("TODO currently fails with: …")
@Issue("JENKINS-41854")

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've copied and pasted the existing test case into a new test case and marked it as suggested, leaving the existing test case untouched.

@jglick

jglick commented Jun 5, 2018

Copy link
Copy Markdown
Member

Offhand I think this would require changes in workflow-step-api, workflow-cps, and this plugin to fix, since the flaw is fundamental to how FilePath is being passed around in the APIs.

@basil basil closed this Jun 6, 2018
@basil basil reopened this Jun 6, 2018
@basil

basil commented Jun 6, 2018

Copy link
Copy Markdown
Member Author

Offhand I think this would require changes in workflow-step-api, workflow-cps, and this plugin to fix, since the flaw is fundamental to how FilePath is being passed around in the APIs.

Thanks for explaining, @jglick. Has anyone committed to doing this work? I recognize I'm not the ideal person to work on a complicated change like this (I'm new to Jenkins development), but if nobody else has committed to doing this work I might be willing to give it a shot. I feel an obligation to my users, and this is a big pain point for them. I don't think it's wise for me to give this a shot on my own (given that I'm new to Jenkins development), but I could see this working out if someone was willing to mentor me to implement these changes. So is anyone willing to commit to either fixing the bug, or mentoring me to fix it?

@basil

basil commented Jul 4, 2018

Copy link
Copy Markdown
Member Author

Hi @jglick, a gentle reminder regarding this pull request.

@svanoort svanoort self-assigned this Aug 8, 2018

@dwnusbaum dwnusbaum left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@basil Thanks for adding a reproduction case! I don't think anyone is currently working on the bug, but I also don't have enough knowledge of the necessary changes to be able to mentor you through fixing it. If you're feeling adventurous, you can open a work-in-progress PR that tries to implement Jesses' ideas in the ticket description, and we can try to give guidance there, but I really have no idea of how involved the fix would be.

@abayer abayer left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems worth adding to me.

@dwnusbaum

Copy link
Copy Markdown
Member

Resolved a merge conflict with #73, will merge once the CI build passes.

@dwnusbaum
dwnusbaum merged commit 4d61eee into jenkinsci:master Aug 22, 2018
@basil
basil deleted the JENKINS-41854 branch September 19, 2018 23:34
orgi pushed a commit to orgi/workflow-durable-task-step-plugin that referenced this pull request Nov 13, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants