Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-68863

[Regression] Any config change makes Jenkins crash

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • jobconfighistory-plugin
    • None

      I probably found a race condition for this plugin.

      Bellow you got an INFO logs from Safe restart.
      This is from start to throwing an unhanded error and permanent stop.

      webroot: EnvVars.masterEnvVars.get("JENKINS_HOME")
2022-06-28 17:16:57.984+0000 [id=1]     INFO    org.eclipse.jetty.util.log.Log#initialized: Logging initialized @3820ms to org.eclipse.jetty.util.log.JavaUtilLog
2022-06-28 17:16:58.506+0000 [id=1]     INFO    winstone.Logger#logInternal: Beginning extraction from war file
2022-06-28 17:16:58.622+0000 [id=1]     WARNING o.e.j.s.handler.ContextHandler#setContextPath: Empty contextPath
2022-06-28 17:16:59.102+0000 [id=1]     INFO    org.eclipse.jetty.server.Server#doStart: jetty-9.4.46.v20220331; built: 2022-03-31T16:38:08.030Z; git: bc17a0369a11ecf40bb92c839b9ef0a8ac50ea18; jvm 17.0.3+7
2022-06-28 17:17:00.208+0000 [id=1]     INFO    o.e.j.w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
2022-06-28 17:17:00.383+0000 [id=1]     INFO    o.e.j.s.s.DefaultSessionIdManager#doStart: DefaultSessionIdManager workerName=node0
2022-06-28 17:17:00.384+0000 [id=1]     INFO    o.e.j.s.s.DefaultSessionIdManager#doStart: No SessionScavenger set, using defaults
2022-06-28 17:17:00.390+0000 [id=1]     INFO    o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms
2022-06-28 17:17:03.401+0000 [id=1]     INFO    hudson.WebAppMain#contextInitialized: Jenkins home directory: /var/jenkins_home found at: EnvVars.masterEnvVars.get("JENKINS_HOME")
2022-06-28 17:17:04.164+0000 [id=1]     INFO    o.e.j.s.handler.ContextHandler#doStart: Started w.@2f6bbeb0{Jenkins v2.356,/,file:///var/jenkins_home/war/,AVAILABLE}{/var/jenkins_home/war}
2022-06-28 17:17:04.287+0000 [id=1]     INFO    o.e.j.server.AbstractConnector#doStart: Started ServerConnector@7c6908d7{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2022-06-28 17:17:04.292+0000 [id=1]     INFO    org.eclipse.jetty.server.Server#doStart: Started @10132ms
2022-06-28 17:17:04.307+0000 [id=26]    INFO    winstone.Logger#logInternal: Winstone Servlet Engine running: controlPort=disabled
2022-06-28 17:17:05.365+0000 [id=32]    INFO    jenkins.InitReactorRunner$1#onAttained: Started initialization
2022-06-28 17:17:06.476+0000 [id=31]    INFO    jenkins.InitReactorRunner$1#onAttained: Listed all plugins
2022-06-28 17:17:24.768+0000 [id=33]    INFO    jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
2022-06-28 17:17:24.885+0000 [id=36]    INFO    jenkins.InitReactorRunner$1#onAttained: Started all plugins
2022-06-28 17:17:24.911+0000 [id=37]    INFO    jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
2022-06-28 17:17:31.311+0000 [id=38]    INFO    jenkins.InitReactorRunner$1#onAttained: System config loaded
2022-06-28 17:17:32.217+0000 [id=38]    INFO    jenkins.InitReactorRunner$1#onAttained: System config adapted
2022-06-28 17:17:32.218+0000 [id=38]    INFO    jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
2022-06-28 17:17:32.275+0000 [id=37]    INFO    jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
2022-06-28 17:17:32.369+0000 [id=52]    INFO    hudson.model.AsyncPeriodicWork#lambda$doRun$1: Started Download metadata
2022-06-28 17:17:32.390+0000 [id=52]    INFO    hudson.model.AsyncPeriodicWork#lambda$doRun$1: Finished Download metadata. 16 ms
2022-06-28 17:17:32.981+0000 [id=35]    INFO    jenkins.InitReactorRunner$1#onAttained: Completed initialization
2022-06-28 17:17:33.101+0000 [id=25]    INFO    hudson.lifecycle.Lifecycle#onReady: Jenkins is fully up and running
2022-06-28 17:23:59.727+0000 [id=81]    INFO    hudson.model.UpdateCenter#doUpgrade: Scheduling the core upgrade
2022-06-28 17:24:02.430+0000 [id=90]    INFO    h.model.UpdateCenter$DownloadJob#run: Starting the installation of jenkins.war on behalf of dumam
2022-06-28 17:24:02.820+0000 [id=21]    INFO    hudson.model.UpdateCenter#doSafeRestart: Scheduling Jenkins reboot
2022-06-28 17:24:03.921+0000 [id=90]    INFO    h.m.UpdateCenter$UpdateCenterConfiguration#download: Downloading jenkins.war
2022-06-28 17:24:14.373+0000 [id=90]    INFO    h.model.UpdateCenter$DownloadJob#run: Installation successful: jenkins.war
2022-06-28 17:24:14.381+0000 [id=97]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Restart in 10 seconds
2022-06-28 17:24:24.382+0000 [id=97]    INFO    hudson.lifecycle.Lifecycle#onStop: Stopping Jenkins as requested by dumam
2022-06-28 17:24:24.386+0000 [id=97]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
2022-06-28 17:24:24.430+0000 [id=97]    INFO    jenkins.model.Jenkins$16#onAttained: Started termination
2022-06-28 17:24:24.470+0000 [id=97]    INFO    jenkins.model.Jenkins$16#onAttained: Completed termination
2022-06-28 17:24:24.471+0000 [id=97]    INFO    jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection
2022-06-28 17:24:24.506+0000 [id=97]    INFO    jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager
2022-06-28 17:24:24.523+0000 [id=97]    INFO    jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue
2022-06-28 17:24:24.570+0000 [id=97]    WARNING h.m.listeners.SaveableListener#fireOnChange
java.lang.NullPointerException: Cannot invoke "hudson.plugins.jobConfigHistory.JobConfigHistory.isSaveable(hudson.model.Saveable, hudson.XmlFile)" because "plugin" is null
        at hudson.plugins.jobConfigHistory.JobConfigHistorySaveableListener.onChange(JobConfigHistorySaveableListener.java:59)
        at hudson.model.listeners.SaveableListener.fireOnChange(SaveableListener.java:82)
        at hudson.model.Queue.save(Queue.java:478)
        at jenkins.model.Jenkins._cleanUpPersistQueue(Jenkins.java:3842)
        at jenkins.model.Jenkins.cleanUp(Jenkins.java:3597)
        at hudson.lifecycle.ExitLifecycle.restart(ExitLifecycle.java:67)
        at jenkins.model.Jenkins$20.run(Jenkins.java:4568)
2022-06-28 17:24:24.572+0000 [id=97]    INFO    jenkins.model.Jenkins#_cleanUpAwaitDisconnects: Waiting for node disconnection completion
2022-06-28 17:24:24.573+0000 [id=97]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Jenkins stopped

      This happens always when Jenkins have to do some stuff around main config.
      So far I founded that this actions triggers this behavior:
      -> plugin update
      -> core update

      At first my guess was that during upgrade from 1148.v8607da_ef251e to 1155.v28a_46a_cc06a_5 some error was introduced, but this happen also for other plugins and core.
      From first glance it looks like Jenkins or GC freed memory for plugin object and then tried to save something to it. I recently changed java 11 to java 17 so I guess this is a source of error.
      I will try to downgrade to 11 and check if this issue remain.

            Unassigned Unassigned
            dumam Bartosz Nowak
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated: