[1.0.7] untilEach watch closure fails to watch Build with Docker source and postCommit hook

[arnaud-deprez]

Hi,

I could reproduce it on Openshift v3.9.0 (minishift) with the default jenkins (jenkins-client-plugin:1.0.7)

It might be related to #130 but I'm not sure.

Typically, I have in my jenkins pipeline a script like:

openshift.withCluster() {
  openshift.withProject(project) {
    def build = openshift.process(readFile("$image/openshift/build-template.yml"))
    def buildDockerConfig = openshift.apply(build).narrow('bc')
    echo "Start building docker image: $image"
    def buildSelector = buildDockerConfig.startBuild("--from-dir=$image")
    timeout(time: 10, unit: 'MINUTES') {
      buildSelector.untilEach(1) {
        return it.object().status.phase == "Complete"
      }
    }
  }
}

While this is working with regular openshift docker build strategy, it fails if I add a postCommit hook.

When it fails, I got a:

java.lang.InterruptedException: sleep interrupted

Any idea ?

[gabemontero]

Yeah untilEach calls withEach which is a nexus of the issues you mentioned.

I'm going to close this out in the interim then. But if it is possible for you, try installing the pre-release patch at #130 (comment) and see if your issues persists.

If it does, reopen, and provide both the entire jenkins pod logs and entire job run log, and we'll go from there.

thanks

[arnaud-deprez]

Hi @gabemontero

I tested with your pre-release and the problem is still there.
May I suggest to reopen this issue ?

I'm not sure it's the same issue as I also got this problem in openshift 3.7 (minishift 3.7.2), reason why I upgraded to 3.9.0.

Regards,

[gabemontero]

On Mon, Apr 9, 2018 at 11:56 AM Arnaud Deprez ***@***.***> wrote: Hi @gabemontero <https://github.com/gabemontero> I tested with your pre-release and the problem is still there. May I suggest to reopen this issue ? I'm not sure it's the same issue as I also got this problem in openshift 3.7 (minishift 3.7.2), reason why I upgraded to 3.9.0. Regards,

yes reopen and provide the data I mentioned

…

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#140 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADbadKkHKhuWzu4ffCQDewG7QUCl7r94ks5tm4SjgaJpZM4TMvaw> .

[arnaud-deprez]

I don't have much logs actually :-(.
I will try to simplify what I'm doing in a simple example but I will need a bit of time.

[gabemontero]

On Mon, Apr 9, 2018 at 12:19 PM, Arnaud Deprez ***@***.***> wrote: I don't have much logs actually :-(. I will try to simplify what I'm doing in a simple example but I will need a bit of time.

OK ... likewise, if you provide the bc yaml, including all of that `build-template.yml`, we can see about constructing a similar reproducer. Also, `oc get events` and an `oc get build -o yaml` for the build you are starting from the pipeline, it might provide some useful details on what the postCommit hook is doing for you while this is running. My guess is that with your post commit hook, the build is not completing within the 1 minute time out and the pipeline exits with an error.

…

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#140 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADbadLyWXBJgj0BWdTGTpsClxnHZQqzHks5tm4ongaJpZM4TMvaw> .

[arnaud-deprez]

@gabemontero Negative :-)
The docker build with postCommit hook finish successfully but the check in the pipeline fails.

I'll give you an example

[arnaud-deprez]

Hi @gabemontero,

After some investigation and having simplify my pipeline, it seems to be a concurrency problem.

Here is my pipeline:

def buildImage(image) {
    openshift.withCluster() {
        openshift.withProject('cicd') {
            def build = openshift.process(readFile("$image/openshift/build-template.yml"))
            def buildDockerConfig = openshift.apply(build).narrow('bc')
            echo "Start building docker image: $image"
            def buildSelector = buildDockerConfig.startBuild("--from-dir=$image")
            timeout(time: 10, unit: 'MINUTES') {
                // TODO: report this fails on build with postCommit hook
                buildSelector.untilEach(1) {
                    return it.object().status.phase == "Complete"
                }
            }
        }
    }
}

pipeline { 
    agent any
    
    stages {
        stage('Checkout') {
            steps {
                echo "Checkout test branch..."
                git url: 'https://github.com/arnaud-deprez/jenkins-docker-openshift.git', branch: 'test'
            }
        }
        stage('Build') {
            /*
            This is working!
            steps {
                buildImage('slave-gradle')
            }
            */
            // This is NOT working!
            failFast true
            parallel {
                stage('gradle slave') {
                    steps {
                        buildImage('slave-gradle')
                    }
                }
                stage('nodejs slave') {
                    steps {
                        buildImage('slave-nodejs')
                    }
                }
            }
        }
    }
}

It assumes you are working on a cicd project.

The build configs are available in my github project in testbranch https://github.com/arnaud-deprez/jenkins-docker-openshift/tree/test under slave-gradleand slave-nodejs.

Basically, I'm trying to define a set of builds/pipeline to build jenkins and its slaves, test the setup and promote the image to upgrade the current the setup so it can all be done automatically.

Here is the exception I got now:

hudson.AbortException: Unable to retrieve object names: selector([name=null],[labels=null],[list=[build/jenkins-slave-nodejs-centos7-docker-2]]); action failed: {reference={}, err=, verb=get, cmd=oc --server=https://172.30.0.1:443 --certificate-authority=/var/run/secrets/kubernetes.io/serviceaccount/ca.crt --namespace=cicd --token=XXXXX get build/jenkins-slave-nodejs-centos7-docker-2 -o=name --ignore-not-found , out=, status=143}
	at com.openshift.jenkins.plugins.pipeline.OcAction$OcActionResult.failIf(OcAction.java:119)
	at sun.reflect.GeneratedMethodAccessor1004.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:93)
	at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
	at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1213)
	at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1022)
	at org.codehaus.groovy.runtime.callsite.PojoMetaClassSite.call(PojoMetaClassSite.java:47)
	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
	at com.cloudbees.groovy.cps.sandbox.DefaultInvoker.methodCall(DefaultInvoker.java:19)
	at com.openshift.jenkins.plugins.OpenShiftDSL$OpenShiftResourceSelector.queryNames(jar:file:/var/lib/jenkins/plugins/openshift-client/WEB-INF/lib/openshift-client.jar!/com/openshift/jenkins/plugins/OpenShiftDSL.groovy:1202)
	at com.openshift.jenkins.plugins.OpenShiftDSL$OpenShiftResourceSelector.count(jar:file:/var/lib/jenkins/plugins/openshift-client/WEB-INF/lib/openshift-client.jar!/com/openshift/jenkins/plugins/OpenShiftDSL.groovy:1175)
	at com.openshift.jenkins.plugins.OpenShiftDSL$OpenShiftResourceSelector.untilEach(jar:file:/var/lib/jenkins/plugins/openshift-client/WEB-INF/lib/openshift-client.jar!/com/openshift/jenkins/plugins/OpenShiftDSL.groovy:1103)
	at com.openshift.jenkins.plugins.OpenShiftDSL$OpenShiftResourceSelector.watch(jar:file:/var/lib/jenkins/plugins/openshift-client/WEB-INF/lib/openshift-client.jar!/com/openshift/jenkins/plugins/OpenShiftDSL.groovy:1082)
	at ___cps.transform___(Native Method)
	at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:57)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82)
	at sun.reflect.GeneratedMethodAccessor170.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72)
	at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:60)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixArg(FunctionCallBlock.java:82)
	at sun.reflect.GeneratedMethodAccessor170.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72)
	at com.cloudbees.groovy.cps.impl.ContinuationGroup.methodCall(ContinuationGroup.java:60)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:109)
	at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixName(FunctionCallBlock.java:77)
	at sun.reflect.GeneratedMethodAccessor172.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	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: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:122)
	at org.codehaus.groovy.runtime.GroovyCategorySupport.use(GroovyCategorySupport.java:261)
	at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:163)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.access$001(SandboxContinuable.java:19)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:35)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:32)
	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.GroovySandbox.runInSandbox(GroovySandbox.java:108)
	at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.run0(SandboxContinuable.java:32)
	at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:174)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.run(CpsThreadGroup.java:331)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup.access$100(CpsThreadGroup.java:82)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:243)
	at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$2.call(CpsThreadGroup.java:231)
	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:112)
	at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
Caused: java.util.concurrent.ExecutionException
	at org.jenkinsci.plugins.workflow.cps.CpsBodyExecution.get(CpsBodyExecution.java:297)
	at com.openshift.jenkins.plugins.pipeline.OcWatch$Execution.run(OcWatch.java:159)
	at com.openshift.jenkins.plugins.pipeline.OcWatch$Execution.run(OcWatch.java:79)
	at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1$1.call(AbstractSynchronousNonBlockingStepExecution.java:47)
	at hudson.security.ACL.impersonate(ACL.java:260)
	at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44)
	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: FAILURE

[arnaud-deprez]

I manage to avoid this problem by checking the status of each build synchronously:

openshift.selector('BuildConfig', [build: 'jenkins', strategy: 'docker']).withEach {
  def buildSelector = it.related('builds')
  timeout(time: 10, unit: 'MINUTES') {
    buildSelector.untilEach(1) {
      return it.object().status.phase == "Complete"
    }
  }
}

[gabemontero]

OK, the parallel processing help shed some light @arnaud-deprez and the data helps progress things for me. It also generates some additional questions:

1. based on this portion of the stack:

Caused: java.util.concurrent.ExecutionException
	at org.jenkinsci.plugins.workflow.cps.CpsBodyExecution.get(CpsBodyExecution.java:297)
	at com.openshift.jenkins.plugins.pipeline.OcWatch$Execution.run(OcWatch.java:159)

You should have seen a message in the console log for the run generated by this code:

                                    } catch (Exception t) {
                                        String exceptionMsgs = t.getMessage();
                                        if (t.getCause() != null) {
                                            exceptionMsgs = exceptionMsgs + "; " + t.getCause().getMessage();
                                        }
                                        listener.getLogger().println(String.format("\nwatch closure threw an exception: \"%s\".\n", exceptionMsgs));
                                        getContext().onFailure(t);
                                        return null;
                                    }

It should have some cause information that would be potentially relevant. Did you see anything with watch closure threw an exception:

Also, I presume that was a prior incarnation of the pipeline, but same core result, as you sample in #140 (comment) does not have a call to openshift.watch.

Pending those clarifications, we could easily be hitting a Jenkins bug/limitation wrt pipelines. Simple google searches will show you that concurrency with that stuff is not the greatest. Or it could point to some concurrency hiccup on the openshift side trying to get a build that is in the process of being updated or something.

Hopefully you've got some messages there that we can work off of.

In the interim, I'll see if I can stand up your example and replicate. Will hopefully be sometime my time on Wednesday.

[gabemontero]

OK, using @arnaud-deprez example as a template, I've reproduced this (though it manifests slightly differently), though it manifests slightly differently.

The post-commit element is not the cause .. it just affects the timing such that @arnaud-deprez hits the concurrency issue in CpsStepContext.

In my flavor, I'm getting the concurrency issue via:

Apr 12, 2018 9:21:17 PM org.jenkinsci.plugins.workflow.cps.CpsStepContext completed
WARNING: already completed CpsStepContext[40:_OcWatch]:Owner[asdf/12:asdf #12]
java.lang.IllegalStateException: delivered here
	at org.jenkinsci.plugins.workflow.cps.CpsStepContext.completed(CpsStepContext.java:353)
	at org.jenkinsci.plugins.workflow.cps.CpsStepContext.onSuccess(CpsStepContext.java:333)
	at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44)
	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)

Apr 12, 2018 9:21:17 PM org.jenkinsci.plugins.workflow.cps.CpsStepContext completed
INFO: new success: null
Apr 12, 2018 9:21:17 PM org.jenkinsci.plugins.workflow.cps.CpsStepContext completed
INFO: previously delivered here
java.lang.Throwable
	at org.jenkinsci.plugins.workflow.cps.CpsStepContext.completed(CpsStepContext.java:341)
	at org.jenkinsci.plugins.workflow.cps.CpsStepContext.onFailure(CpsStepContext.java:329)
	at com.openshift.jenkins.plugins.pipeline.OcWatch$Execution.run(OcWatch.java:212)
	at com.openshift.jenkins.plugins.pipeline.OcWatch$Execution.run(OcWatch.java:79)
	at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1$1.call(AbstractSynchronousNonBlockingStepExecution.java:47)
	at hudson.security.ACL.impersonate(ACL.java:290)
	at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44)
	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)

Essentially, the same CpsStepContext is getting called twice. I say that cause I added debug in OcWatch to confirm the objects should be different, and they were in fact different.

However, this got me looking at some javadoc. And I'm not sure we could classify this as a Jenkins bug either.

Some of these older StepExecution classes warn about longer running tasks and running in parallel. And the one we are currently using is deprecated. There are some newer versions of StepExecution which may help, but that would entail bumping our current dependencies. And even then, it might not be sufficient.

Hence, the complexity is such that I don't see a bug level effort getting this done.

So the prudent approach to me seems:

1. document this as a restriction in this plugin ... running watches in parallel is not advised, as invariable results can occur
   as a work around, the can always sh 'oc ...'
2. open a card to investigate bumping the dependencies, and seeing if the newer pipeline support helps.

@bparees fyi / opinions ^^

[arnaud-deprez]

Hi @gabemontero,

Thanks for our investigation, actually to give your more insight, I tried several times and I didn't get exactly the same behaviour each time. That tends me to conclude in your direction that it's not because you will solve one issue that you will not discover another one later or before the problem you've just solved.

So IMO if you allow me, I think we should start with 1 so everyone is aware and then doing 2 as using deprecated stuff is not good especially for having support, isn't ?

[gabemontero]

Yep that is my general think @arnaud-deprez, and thanks, you clarification on the behavior landing slightly differently after subsequent repros does confirm for me as well the timing aspect of this

Pending any objection from @bparees, I'll use this bug to drive 1) and open the trello card for 2)