[JIRA] (JENKINS-57163) Using timestamps prevents parallel thread's catch block from executing sleep

3 views
Skip to first unread message

benkraft@khanacademy.org (JIRA)

unread,
Apr 23, 2019, 9:24:03 PM4/23/19
to jenkinsc...@googlegroups.com
Ben Kraft created an issue
 
Jenkins / Bug JENKINS-57163
Using timestamps prevents parallel thread's catch block from executing sleep
Issue Type: Bug Bug
Assignee: Steven G Brown
Components: timestamper-plugin, workflow-basic-steps-plugin, workflow-cps-plugin
Created: 2019-04-24 01:23
Environment: Jenkins 2.169
Ubuntu 18.04.2
OpenJDK 1.8.1_191

Plugins:
Pipeline 2.6
Pipeline Basic Steps 2.15
Pipeline Groovy 2.67
Timestamper 1.9 (also broken on 1.8.10)
Priority: Major Major
Reporter: Ben Kraft

Some strange interaction between parallel, timestamps, sleep, and try/catch is causing our groovy catch block to stop executing after a sleep. The code below provides the smallest repro I've found: we have a background thread which sets up timestamps and then sleeps for a while; in the foreground we sleep a bit less, then catch any exception, sleeping in the catch block. If the exception is raised (I've just been aborting the job) the part of the catch block after the sleep never executes. Sample log output is below; we expect to see a line saying "slept", but it never shows up.

As far as I can tell, each part of the script below is required to reproduce the issue. In particular, removing the timestamps in the background thread causes the catch to execute as expected. Similarly, various other code instead of the sleep(1) executes just fine. I'm not sure what's going wrong, but it sure seems to me like a bug in some part of how jenkins groovy translates and interprets this code!

Groovy script:

def wrap(Closure body) {
    parallel(
        "_watchdog": {
            timestamps {
                echo("started background sleep");
                sleep(600);
                echo("finished background sleep");
            }
        },
        "main": {
            body();
        },
        "failFast": true,
    );
}


wrap {
    try {
        echo("started sleep");
        sleep(60);
        echo("finished sleep");
    } catch (e) {
        echo("Caught error: ${e}")
        sleep(1);
        echo("slept")
        throw e;
    }
    echo("should never get here");
}

Output:

Started by user Ben Kraft
Running in Durability level: MAX_SURVIVABILITY
[Pipeline] Start of Pipeline
[Pipeline] parallel
[Pipeline] { (Branch: _watchdog)
[Pipeline] { (Branch: main)
[Pipeline] timestamps
[Pipeline] {
[Pipeline] echo
started sleep
[Pipeline] sleep
Sleeping for 1 min 0 sec
[Pipeline] echo
10:39:27 started background sleep
[Pipeline] sleep
10:39:27 Sleeping for 10 min
Aborted by Ben Kraft
[Pipeline] echo
Caught error: org.jenkinsci.plugins.workflow.steps.FlowInterruptedException
[Pipeline] sleep
Sleeping for 1 sec
[Pipeline] }
[Pipeline] // timestamps
[Pipeline] }
Failed in branch _watchdog
[Pipeline] }
Failed in branch main
[Pipeline] // parallel
[Pipeline] End of Pipeline
org.jenkinsci.plugins.workflow.steps.FlowInterruptedException
	at org.jenkinsci.plugins.workflow.cps.CpsBodyExecution.cancel(CpsBodyExecution.java:244)
	at org.jenkinsci.plugins.workflow.steps.BodyExecution.cancel(BodyExecution.java:76)
	at org.jenkinsci.plugins.workflow.cps.steps.ParallelStepExecution.stop(ParallelStepExecution.java:67)
	at org.jenkinsci.plugins.workflow.cps.steps.ParallelStep$ResultHandler$Callback.checkAllDone(ParallelStep.java:147)
	at org.jenkinsci.plugins.workflow.cps.steps.ParallelStep$ResultHandler$Callback.onFailure(ParallelStep.java:134)
	at org.jenkinsci.plugins.workflow.cps.CpsBodyExecution$FailureAdapter.receive(CpsBodyExecution.java:349)
	at com.cloudbees.groovy.cps.impl.ThrowBlock$1.receive(ThrowBlock.java:68)
	at com.cloudbees.groovy.cps.impl.ConstantBlock.eval(ConstantBlock.java:21)
	at com.cloudbees.groovy.cps.Next.step(Next.java:83)
	at com.cloudbees.groovy.cps.Continuable$1.call(Continuable.java:174)
	at com.cloudbees.groovy.cps.Continuable$1.call(Continuable.java:163)
	at org.codehaus.groovy.runtime.GroovyCategorySupport$ThreadCategoryInfo.use(GroovyCategorySupport.java:129)
	at org.codehaus.groovy.runtime.GroovyCategorySupport.use(GroovyCategorySupport.java:268)
	at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:163)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.access$101(SandboxContinuable.java:34)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.lambda$run0$0(SandboxContinuable.java:59)
	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.GroovySandbox.runInSandbox(GroovySandbox.java:136)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.run0(SandboxContinuable.java:58)
	at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:182)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.run(CpsThreadGroup.java:332)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.access$200(CpsThreadGroup.java:83)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:244)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:232)
	at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$2.call(CpsVmExecutorService.java:64)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:131)
	at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
	at jenkins.security.ImpersonatingExecutorService$1.run(ImpersonatingExecutorService.java:59)
	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:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Finished: ABORTED
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.11.2#711002-sha1:fdc329d)

benkraft@khanacademy.org (JIRA)

unread,
Apr 23, 2019, 9:29:03 PM4/23/19
to jenkinsc...@googlegroups.com
Ben Kraft updated an issue
Change By: Ben Kraft
Some strange interaction between parallel, timestamps, sleep, and try/catch is causing our groovy {{catch}} block to stop executing after a {{sleep}}.  The code below provides the smallest repro I've found: we have a background thread which sets up {{timestamps}} and then sleeps for a while; in the foreground we sleep a bit less, then catch any exception, sleeping in the {{catch}} block.  If the exception is raised (I've just been aborting the job) the part of the {{catch}} block after the {{sleep}} never executes.  Sample log output is below; we expect to see a line saying "slept", but it never shows up.

As far as I can tell, each part of the script below is required to reproduce the issue.  In particular, removing the timestamps in the background thread causes the {{catch}} to execute as expected.
  (Note that removing that {{timestamps}} and adding one around {{body}} or around the toplevel job does not reproduce!)   Similarly, various other code instead of the {{sleep(1)}} executes just fine.  I'm not sure what's going wrong, but it sure seems to me like a bug in some part of how jenkins groovy translates and interprets this code!

Groovy script:
{code}

def wrap(Closure body) {
    parallel(
        "_watchdog": {
            timestamps {
                echo("started background sleep");
                sleep(600);
                echo("finished background sleep");
            }
        },
        "main": {
            body();
        },
        "failFast": true,
    );
}


wrap {
    try {
        echo("started sleep");
        sleep(60);
        echo("finished sleep");
    } catch (e) {
        echo("Caught error: ${e}")
        sleep(1);
        echo("slept")
        throw e;
    }
    echo("should never get here");
}
{code}

Output:
{code}
{code}

me@basilcrow.com (JIRA)

unread,
Feb 26, 2020, 2:27:02 PM2/26/20
to jenkinsc...@googlegroups.com
Basil Crow assigned an issue to Unassigned
Change By: Basil Crow
Assignee: Steven G Brown
This message was sent by Atlassian Jira (v7.13.12#713012-sha1:6e07c38)
Atlassian logo
Reply all
Reply to author
Forward
0 new messages