still seeing some build config watch timing issues

[gabemontero]

Using v0.1.7 of the plugin in the openshift jenkins 2 centos image. Ran

1. Cesar's "localup" against a 1.5 pre-release version of origin I build this AM:

openshift v1.5.0-alpha.2+8de00d3-555
kubernetes v1.5.2+43a9be4

2. oc create on a jenkins strategy BC

3. waited for jenkins to get auto provisioned

4. oc start-build on the BC

5. get this error in the jenkins log:

Feb 13, 2017 4:23:46 PM io.fabric8.jenkins.openshiftsync.BuildConfigWatcher onInitialBuildConfigs
SEVERE: Failed to update job
java.lang.IllegalArgumentException: myproject-sample-pipeline-openshift-client-plugin already exists
	at hudson.model.Items.verifyItemDoesNotAlreadyExist(Items.java:462)
	at hudson.model.ItemGroupMixIn.createProjectFromXML(ItemGroupMixIn.java:263)
	at jenkins.model.Jenkins.createProjectFromXML(Jenkins.java:3781)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$2.call(BuildConfigWatcher.java:214)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$2.call(BuildConfigWatcher.java:159)
	at hudson.security.ACL.impersonate(ACL.java:221)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.upsertJob(BuildConfigWatcher.java:159)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.onInitialBuildConfigs(BuildConfigWatcher.java:129)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.access$200(BuildConfigWatcher.java:65)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$1.doRun(BuildConfigWatcher.java:88)
	at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:50)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	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)

It has been intermittent for me (I've seen this twice in the last week or so). I'll try to gather some sync plugin trace with existing version, or add a debug jar, if I can repro with any consistency.

[gabemontero]

The associated job actually completes in jenkins, though the associated build in openshift is never marked as being complete. Its status is still New.

[gabemontero]

@bparees seen it again for the first time in 3 days. Captured more of the log this time. It occurred after a Jenkins restart. I believe it disproves my theory of 2 BuildConfigWatchers running:

Feb 16, 2017 10:29:24 PM INFO io.fabric8.jenkins.openshiftsync.GlobalPluginConfiguration$1 doRun
Waiting for Jenkins to be started
Feb 16, 2017 10:29:24 PM INFO io.fabric8.jenkins.openshiftsync.BuildConfigWatcher start
Now handling startup build configs!!
Feb 16, 2017 10:29:25 PM INFO jenkins.InitReactorRunner$1 onAttained
Loaded all jobs
Feb 16, 2017 10:29:25 PM INFO hudson.model.AsyncPeriodicWork$1 run
Started Download metadata
Feb 16, 2017 10:29:25 PM INFO jenkins.InitReactorRunner$1 onAttained
Completed initialization
Feb 16, 2017 10:29:25 PM INFO hudson.model.AsyncPeriodicWork$1 run
Finished Download metadata. 9 ms
Feb 16, 2017 10:29:25 PM INFO org.springframework.context.support.AbstractApplicationContext prepareRefresh
Refreshing org.springframework.web.context.support.StaticWebApplicationContext@6bb8bec6: display name [Root WebApplicationContext]; startup date [Thu Feb 16 22:29:25 UTC 2017]; root of context hierarchy
Feb 16, 2017 10:29:25 PM INFO org.springframework.context.support.AbstractApplicationContext obtainFreshBeanFactory
Bean factory for application context [org.springframework.web.context.support.StaticWebApplicationContext@6bb8bec6]: org.springframework.beans.factory.support.DefaultListableBeanFactory@566ba5ed
Feb 16, 2017 10:29:25 PM INFO org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@566ba5ed: defining beans [filter,legacy]; root of factory hierarchy
Feb 16, 2017 10:29:26 PM INFO hudson.WebAppMain$3 run
Jenkins is fully up and running
Feb 16, 2017 10:29:26 PM SEVERE io.fabric8.jenkins.openshiftsync.BuildConfigWatcher onInitialBuildConfigs
Failed to update job
java.lang.IllegalArgumentException: myproject-sample-pipeline-openshift-client-plugin already exists
	at hudson.model.Items.verifyItemDoesNotAlreadyExist(Items.java:462)
	at hudson.model.ItemGroupMixIn.createProjectFromXML(ItemGroupMixIn.java:263)
	at jenkins.model.Jenkins.createProjectFromXML(Jenkins.java:3781)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$2.call(BuildConfigWatcher.java:214)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$2.call(BuildConfigWatcher.java:159)
	at hudson.security.ACL.impersonate(ACL.java:221)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.upsertJob(BuildConfigWatcher.java:159)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.onInitialBuildConfigs(BuildConfigWatcher.java:129)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher.access$200(BuildConfigWatcher.java:65)
	at io.fabric8.jenkins.openshiftsync.BuildConfigWatcher$1.doRun(BuildConfigWatcher.java:88)
	at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:50)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	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)

I'm not wondering if this log occurring before BuildConfigWatcher running is indicative:

Feb 16, 2017 10:29:25 PM INFO jenkins.InitReactorRunner$1 onAttained
Loaded all jobs

In other words, Jenkins loaded the existing job before sync plugin pulled it from openshift and attempted to load it.

I'll pay attention to some start up sequences on restart when the error does not occur and see if there is validation. If this is validated, then if we can't coordinate with Jenkins, then we just need some error handling on the collision and confirmation the job does in fact exist, where we proceed happily if it does.

[gabemontero]

Sure enough, the loaded all jobs message from jenkins comes before waiting for jenkins to be started from sync plugin when things come up cleanly:

Feb 16, 2017 11:04:14 PM INFO jenkins.InitReactorRunner$1 onAttained
Loaded all jobs
Feb 16, 2017 11:04:14 PM INFO jenkins.InitReactorRunner$1 onAttained
Completed initialization
Feb 16, 2017 11:04:14 PM INFO hudson.model.AsyncPeriodicWork$1 run
Started Download metadata
Feb 16, 2017 11:04:14 PM INFO hudson.model.AsyncPeriodicWork$1 run
Finished Download metadata. 4 ms
Feb 16, 2017 11:04:14 PM INFO io.fabric8.jenkins.openshiftsync.GlobalPluginConfiguration$1 doRun
Waiting for Jenkins to be started
Feb 16, 2017 11:04:14 PM INFO io.fabric8.jenkins.openshiftsync.BuildConfigWatcher start
Now handling startup build configs!!
Feb 16, 2017 11:04:15 PM INFO org.springframework.context.support.AbstractApplicationContext prepareRefresh

I can start working on a fix along with my other current threads.

[bparees]

Ah, that makes sense... we don't normally have scenarios where jenkins is starting w/ the jobs already existing (but certainly w/ persistent storage it is a scenario we need to worry about). thanks @gabemontero

[bparees]

(by "we don't normally have scenarios like that" i mean, we don't normally test them which is probably why no one has seen/reported this)