Proposal: new initialization milestone for configuration-as-code-plugin

[夏润泽]

Hi all：

This question about casc has occurred more frequently after my recent upgrade. Jenkins version (2.176.2) 

CascPlugin version (1.27) I recently upgraded to Jenkins version 2.199 to see who caused the problem (https://issues.jenkins-ci.org/browse/JENKINS-58993) I found out that it was because I used casc to configure K8Clouds, and changes in cloudList would cause jenkins.save () This is the first problem I found, and it may not be the only one, so I suggest setting a more appropriate initialization milestone for casc.

startup log:

```

Picked up JAVA_TOOL_OPTIONS: -Xms512m -Xmx512m -XX:MaxRAM=2g -Dhudson.slaves.NodeProvisioner.initialDelay=20 -Dhudson.slaves.NodeProvisioner.MARGIN=50 -Dhudson.slaves.NodeProvisioner.MARGIN0=0.85 -Dhudson.model.LoadStatistics.clock=5000 -Dhudson.model.LoadStatistics.decay=0.2 -Dhudson.slaves.NodeProvisioner.recurrencePeriod=5000 -verbose:gc -Xloggc:/var/jenkins_home/gc-%t.log -XX:NumberOfGCLogFiles=2 -XX:+UseGCLogFileRotation -XX:GCLogFileSize=100m -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCCause -XX:+PrintTenuringDistribution -XX:+PrintReferenceGC -XX:+PrintAdaptiveSizePolicy -XX:+UseG1GC -XX:+UseStringDeduplication -XX:+ParallelRefProcEnabled -XX:+DisableExplicitGC -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions

Running from: /usr/share/jenkins/jenkins.war

webroot: EnvVars.masterEnvVars.get("JENKINS_HOME")

2019-11-19 03:02:27.156+0000 [id=1] INFO org.eclipse.jetty.util.log.Log#initialized: Logging initialized @673ms to org.eclipse.jetty.util.log.JavaUtilLog

2019-11-19 03:02:27.365+0000 [id=1] INFO winstone.Logger#logInternal: Beginning extraction from war file

2019-11-19 03:02:27.442+0000 [id=1] WARNING o.e.j.s.handler.ContextHandler#setContextPath: Empty contextPath

2019-11-19 03:02:27.554+0000 [id=1] INFO org.eclipse.jetty.server.Server#doStart: jetty-9.4.z-SNAPSHOT; built: 2019-05-02T00:04:53.875Z; git: e1bc35120a6617ee3df052294e433f3a25ce7097; jvm 1.8.0_222-b10

2019-11-19 03:02:28.129+0000 [id=1] INFO o.e.j.w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet

2019-11-19 03:02:28.235+0000 [id=1] INFO o.e.j.s.s.DefaultSessionIdManager#doStart: DefaultSessionIdManager workerName=node0

2019-11-19 03:02:28.235+0000 [id=1] INFO o.e.j.s.s.DefaultSessionIdManager#doStart: No SessionScavenger set, using defaults

2019-11-19 03:02:28.237+0000 [id=1] INFO o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms

Jenkins home directory: /var/jenkins_home found at: EnvVars.masterEnvVars.get("JENKINS_HOME")

2019-11-19 03:02:29.242+0000 [id=1] INFO o.e.j.s.handler.ContextHandler#doStart: Started w.@5d908d47{Jenkins v2.199,/,file:///var/jenkins_home/war/,AVAILABLE}{/var/jenkins_home/war}

2019-11-19 03:02:29.255+0000 [id=1] INFO o.e.j.server.AbstractConnector#doStart: Started ServerConnector@64616ca2{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}

2019-11-19 03:02:29.351+0000 [id=1] INFO org.eclipse.jetty.server.Server#doStart: Started @2868ms

2019-11-19 03:02:29.352+0000 [id=21] INFO winstone.Logger#logInternal: Winstone Servlet Engine v4.0 running: controlPort=disabled

2019-11-19 03:02:31.263+0000 [id=27] INFO jenkins.InitReactorRunner$1#onAttained: Started initialization

2019-11-19 03:02:32.260+0000 [id=26] INFO jenkins.InitReactorRunner$1#onAttained: Listed all plugins

2019-11-19 03:02:33.756+0000 [id=26] INFO ruby.RubyRuntimePlugin#start: Injecting JRuby into XStream

2019-11-19 03:02:59.769+0000 [id=26] INFO jenkins.InitReactorRunner$1#onAttained: Prepared all plugins

2019-11-19 03:03:00.260+0000 [id=27] INFO jenkins.InitReactorRunner$1#onAttained: Started all plugins

2019-11-19 03:03:04.695+0000 [id=27] INFO h.ExtensionFinder$GuiceFinder$FaultTolerantScope$1#error: Failed to instantiate optional component hudson.plugins.build_timeout.operations.AbortAndRestartOperation$DescriptorImpl; skipping

2019-11-19 03:03:05.033+0000 [id=27] INFO jenkins.InitReactorRunner$1#onAttained: Augmented all extensions

2019-11-19 03:03:09.131+0000 [id=27] SEVERE jenkins.model.Jenkins#save: An attempt to save Jenkins'' global configuration before it has been loaded has been made during milestone Augmented all extensions.  This is indicative of a bug in the caller and may lead to full or partial loss of configuration.

java.lang.IllegalStateException: call trace

at jenkins.model.Jenkins.save(Jenkins.java:3299)

at hudson.util.PersistedList.onModified(PersistedList.java:173)

at jenkins.model.Jenkins$CloudList.onModified(Jenkins.java:525)

at hudson.util.PersistedList.replaceBy(PersistedList.java:85)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:18)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:9)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:359)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:271)

at io.jenkins.plugins.casc.ConfigurationAsCode.lambda$configureWith$4(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.invokeWith(ConfigurationAsCode.java:664)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:585)

at io.jenkins.plugins.casc.ConfigurationAsCode.configure(ConfigurationAsCode.java:280)

at io.jenkins.plugins.casc.ConfigurationAsCode.init(ConfigurationAsCode.java:272)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:104)

at hudson.init.TaskMethodFinder$TaskImpl.run(TaskMethodFinder.java:175)

at org.jvnet.hudson.reactor.Reactor.runTask(Reactor.java:296)

at jenkins.model.Jenkins$5.runTask(Jenkins.java:1124)

at org.jvnet.hudson.reactor.Reactor$2.run(Reactor.java:214)

at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117)

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)

2019-11-19 03:03:09.139+0000 [id=27] SEVERE jenkins.InitReactorRunner$1#onTaskFailed: Failed ConfigurationAsCode.init

java.lang.IllegalStateException: An attempt to save the global configuration was made before it was loaded

at jenkins.model.Jenkins.save(Jenkins.java:3308)

at hudson.util.PersistedList.onModified(PersistedList.java:173)

at jenkins.model.Jenkins$CloudList.onModified(Jenkins.java:525)

at hudson.util.PersistedList.replaceBy(PersistedList.java:85)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:18)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:9)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:359)

Caused: io.jenkins.plugins.casc.ConfiguratorException: cloud: Failed to set attribute clouds(class: class hudson.slaves.Cloud, multiple: true)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:361)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:271)

Caused: io.jenkins.plugins.casc.ConfiguratorException: Failed to save hudson.model.Hudson@484ad4e9

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:274)

at io.jenkins.plugins.casc.ConfigurationAsCode.lambda$configureWith$4(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.invokeWith(ConfigurationAsCode.java:664)

Caused: io.jenkins.plugins.casc.ConfiguratorException: jenkins: error configuring 'jenkins' with class io.jenkins.plugins.casc.core.JenkinsConfigurator configurator

at io.jenkins.plugins.casc.ConfigurationAsCode.invokeWith(ConfigurationAsCode.java:670)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:585)

at io.jenkins.plugins.casc.ConfigurationAsCode.configure(ConfigurationAsCode.java:280)

at io.jenkins.plugins.casc.ConfigurationAsCode.init(ConfigurationAsCode.java:272)

Caused: java.lang.reflect.InvocationTargetException

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:104)

Caused: java.lang.Error

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:110)

at hudson.init.TaskMethodFinder$TaskImpl.run(TaskMethodFinder.java:175)

at org.jvnet.hudson.reactor.Reactor.runTask(Reactor.java:296)

at jenkins.model.Jenkins$5.runTask(Jenkins.java:1124)

at org.jvnet.hudson.reactor.Reactor$2.run(Reactor.java:214)

at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117)

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)

2019-11-19 03:03:09.142+0000 [id=20] SEVERE hudson.util.BootFailure#publish: Failed to initialize Jenkins

java.lang.IllegalStateException: An attempt to save the global configuration was made before it was loaded

at jenkins.model.Jenkins.save(Jenkins.java:3308)

at hudson.util.PersistedList.onModified(PersistedList.java:173)

at jenkins.model.Jenkins$CloudList.onModified(Jenkins.java:525)

at hudson.util.PersistedList.replaceBy(PersistedList.java:85)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:18)

at io.jenkins.plugins.casc.impl.attributes.DescribableListAttribute.setValue(DescribableListAttribute.java:9)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:359)

Caused: io.jenkins.plugins.casc.ConfiguratorException: cloud: Failed to set attribute clouds(class: class hudson.slaves.Cloud, multiple: true)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:361)

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:271)

Caused: io.jenkins.plugins.casc.ConfiguratorException: Failed to save hudson.model.Hudson@484ad4e9

at io.jenkins.plugins.casc.BaseConfigurator.configure(BaseConfigurator.java:274)

at io.jenkins.plugins.casc.ConfigurationAsCode.lambda$configureWith$4(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.invokeWith(ConfigurationAsCode.java:664)

Caused: io.jenkins.plugins.casc.ConfiguratorException: jenkins: error configuring 'jenkins' with class io.jenkins.plugins.casc.core.JenkinsConfigurator configurator

at io.jenkins.plugins.casc.ConfigurationAsCode.invokeWith(ConfigurationAsCode.java:670)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:694)

at io.jenkins.plugins.casc.ConfigurationAsCode.configureWith(ConfigurationAsCode.java:585)

at io.jenkins.plugins.casc.ConfigurationAsCode.configure(ConfigurationAsCode.java:280)

at io.jenkins.plugins.casc.ConfigurationAsCode.init(ConfigurationAsCode.java:272)

Caused: java.lang.reflect.InvocationTargetException

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:104)

Caused: java.lang.Error

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:110)

at hudson.init.TaskMethodFinder$TaskImpl.run(TaskMethodFinder.java:175)

at org.jvnet.hudson.reactor.Reactor.runTask(Reactor.java:296)

at jenkins.model.Jenkins$5.runTask(Jenkins.java:1124)

at org.jvnet.hudson.reactor.Reactor$2.run(Reactor.java:214)

at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117)

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)

Caused: org.jvnet.hudson.reactor.ReactorException

at org.jvnet.hudson.reactor.Reactor.execute(Reactor.java:282)

at jenkins.InitReactorRunner.run(InitReactorRunner.java:48)

at jenkins.model.Jenkins.executeReactor(Jenkins.java:1158)

at jenkins.model.Jenkins.<init>(Jenkins.java:965)

at hudson.model.Hudson.<init>(Hudson.java:85)

at hudson.model.Hudson.<init>(Hudson.java:81)

at hudson.WebAppMain$3.run(WebAppMain.java:233)

Caused: hudson.util.HudsonFailedToLoad

at hudson.WebAppMain$3.run(WebAppMain.java:250)

2019-11-19 03:03:09.150+0000 [id=20] INFO jenkins.model.Jenkins#cleanUp: Stopping Jenkins

2019-11-19 03:03:09.327+0000 [id=26] WARNING hudson.model.ComputerSet#<clinit>: Failed to instantiate NodeMonitors

java.nio.channels.ClosedByInterruptException

at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)

at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:164)

at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:65)

at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:109)

at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)

at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)

at java.io.BufferedInputStream.read(BufferedInputStream.java:265)

at java.io.FilterInputStream.read(FilterInputStream.java:83)

at java.io.PushbackInputStream.read(PushbackInputStream.java:139)

at com.thoughtworks.xstream.core.util.XmlHeaderAwareReader.getHeader(XmlHeaderAwareReader.java:79)

at com.thoughtworks.xstream.core.util.XmlHeaderAwareReader.<init>(XmlHeaderAwareReader.java:61)

at com.thoughtworks.xstream.io.xml.AbstractXppDriver.createReader(AbstractXppDriver.java:65)

Caused: com.thoughtworks.xstream.io.StreamException:  : null

at com.thoughtworks.xstream.io.xml.AbstractXppDriver.createReader(AbstractXppDriver.java:69)

at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1053)

at hudson.XmlFile.read(XmlFile.java:147)

Caused: java.io.IOException: Unable to read /var/jenkins_home/nodeMonitors.xml

at hudson.XmlFile.read(XmlFile.java:149)

at hudson.model.ComputerSet.<clinit>(ComputerSet.java:445)

at jenkins.metrics.impl.JenkinsHealthCheckProviderImpl.getHealthChecks(JenkinsHealthCheckProviderImpl.java:89)

at jenkins.metrics.api.HealthCheckProviderListener.onChange(HealthCheckProviderListener.java:93)

at jenkins.metrics.api.HealthCheckProviderListener.attach(HealthCheckProviderListener.java:79)

at jenkins.metrics.api.Metrics.afterExtensionsAugmented(Metrics.java:314)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:498)

at hudson.init.TaskMethodFinder.invoke(TaskMethodFinder.java:104)

at hudson.init.TaskMethodFinder$TaskImpl.run(TaskMethodFinder.java:175)

at org.jvnet.hudson.reactor.Reactor.runTask(Reactor.java:296)

at jenkins.model.Jenkins$5.runTask(Jenkins.java:1124)

at org.jvnet.hudson.reactor.Reactor$2.run(Reactor.java:214)

at org.jvnet.hudson.reactor.Reactor$Node.run(Reactor.java:117)

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)

2019-11-19 03:03:09.340+0000 [id=20] INFO jenkins.model.Jenkins$18#onAttained: Started termination

2019-11-19 03:03:09.365+0000 [id=20] INFO jenkins.model.Jenkins$18#onAttained: Completed termination

2019-11-19 03:03:09.365+0000 [id=20] INFO jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection

2019-11-19 03:03:09.367+0000 [id=20] INFO jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager

2019-11-19 03:03:09.441+0000 [id=20] INFO jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue

2019-11-19 03:03:09.457+0000 [id=20] INFO jenkins.model.Jenkins#cleanUp: Jenkins stopped

```

[Oleg Nenashev]

https://issues.jenkins-ci.org/browse/JENKINS-51856 is probably the better task.

Introducing new milestones has been discussed and agreed at the JCasC project meetings before, so it is rather a matter of a reference implementation for JEP.

BR, Oleg

[夏润泽]

Thank you for your reply, please let me know if I can help.

Best

RunZe Xia

[James Nord]

If you (or someone) wants to try a quick and dirty quick fix (until the required milestones are available) then sleeping an amount of time if a system property is set would be a temporary hackish workaround.

https://github.com/jenkinsci/configuration-as-code-plugin/blob/c7864838afa0c96b3469748000cf8684d1832883/plugin/src/main/java/io/jenkins/plugins/casc/ConfigurationAsCode.java#L272

    @Initializer(after = InitMilestone.EXTENSIONS_AUGMENTED, before = InitMilestone.JOB_LOADED)

    public static void init() throws Exception {

        Long duration = Long.getLong(this.getClass().getName() + ".initialDelay")

        if (duration != null) {

          try {

            Thread.sleep(duration);

          } catch (InteruptedException e) {

            LOGGER.log(Level.WARNING, "interupted whilst delaying startup", e);

          }

        }        

        detectVaultPluginMissing();

        get().configure();

[Oleg Nenashev]

That fix is indeed dirty, but it might be acceptable.

Our problem is that it is going to land in LTS in one month unless we take a baseline before 2.198

[James Nord]

https://github.com/jenkinsci/configuration-as-code-plugin/pull/1204

manipluating Jenkins internal state whilst it is being loaded is equally hacky.

> Our problem is that it is going to land in LTS in one month unless we take a baseline before 2.198

you actually DO want this code to be in.  there are people reporting that Config-as-Code does not work correctly and I bet you a chocolate bar that it is because of this. so you can have a deterministic system or an unreliable system without all the configuration loaded correctly which may cause dataloss.  I would pick deterministic every day.

The whole point of the initial code was to stop non deterministic random race conditions to occur and it is doing its job perfectly well.   

Or someone (not me because I think it is a bad idea) enhance the code in Jenkins to not throw the  exception and blindly continue knowing there may be dataloss if someone sets a system property / flag along the lines of I_DO_NOT_CARE_ABOUT_DATALOSS=true

/James

[夏润泽]

The whole point of the initial code was to stop non deterministic random race conditions to occur and it is doing its job perfectly well.   

 

Yes, deterministic is very important. I think this fix is necessary until the new milestone is introduced.

I also agree with the workaround https://github.com/jenkinsci/configuration-as-code-plugin/pull/1204, which can reduce the probability of initialization failure.

I will test this part of the code in my environment.

Best

RunZeXia

[James Nord]

Thanks RunZeXia,

Please let me know how you get on with this as it being discussed in the next LTS selection thread. (https://groups.google.com/forum/#!topic/jenkinsci-dev/2hPMwmZDZFg)

/James