[JIRA] (JENKINS-59992) "Jenkins.instance is missing" error when restarting Jenkins

46 views
Skip to first unread message

craig.lutgen@cybersecureips.com (JIRA)

unread,
Oct 30, 2019, 6:23:03 PM10/30/19
to jenkinsc...@googlegroups.com
Craig Lutgen created an issue
 
Jenkins / Bug JENKINS-59992
"Jenkins.instance is missing" error when restarting Jenkins
Issue Type: Bug Bug
Assignee: Unassigned
Components: core
Created: 2019-10-30 22:22
Environment: Windows Server 2016
Java 1.8.0_221-b.11
Jenkins 2.202

IIS Reverse proxy configured per https://wiki.jenkins.io/display/JENKINS/Running+Jenkins+behind+IIS

CSRF Protection w/ Default Crumb Issuer

Priority: Minor Minor
Reporter: Craig Lutgen

Auto-Upgrade Jenkins, select Restart Jenkins when complete...

Manual restart via https://<jenkins>/restart...

 

Logs (see below) show shutdown and restart occurs. However, during startup, an infinite cycle of exceptions (Jenkins.instance is missing) see below. Must manually restart windows service to successfully restart jenkins.

 

2019-10-30 19:58:18.332+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Starting the installation of jenkins.war on behalf of xxxxx2019-10-30 19:58:18.332+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Starting the installation of jenkins.war on behalf of xxxxx2019-10-30 19:58:18.532+0000 [id=154905] INFO h.m.UpdateCenter$UpdateCenterConfiguration#download: Downloading jenkins.war2019-10-30 19:58:23.497+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Installation successful: jenkins.war2019-10-30 20:01:07.466+0000 [id=151608] INFO hudson.model.UpdateCenter#doSafeRestart: Scheduling Jenkins reboot2019-10-30 20:01:07.478+0000 [id=155008] INFO jenkins.model.Jenkins$23#run: Restart in 10 seconds2019-10-30 20:01:17.479+0000 [id=155008] INFO jenkins.model.Jenkins$23#run: Restarting VM as requested by xxxxx2019-10-30 20:01:17.481+0000 [id=155008] INFO jenkins.model.Jenkins#cleanUp: Stopping Jenkins2019-10-30 20:01:17.529+0000 [id=155008] INFO jenkins.model.Jenkins$18#onAttained: Started termination2019-10-30 20:01:17.542+0000 [id=155008] INFO jenkins.model.Jenkins$18#onAttained: Completed termination2019-10-30 20:01:17.542+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection2019-10-30 20:01:17.550+0000 [id=155008] INFO j.s.DefaultJnlpSlaveReceiver#channelClosed: safe-restart thread for xxxx terminated: java.nio.channels.ClosedChannelException2019-10-30 20:01:17.557+0000 [id=155008] INFO j.s.DefaultJnlpSlaveReceiver#channelClosed: safe-restart thread for xxxx terminated: java.nio.channels.ClosedChannelException2019-10-30 20:01:18.569+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager2019-10-30 20:01:18.596+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue2019-10-30 20:01:18.602+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpAwaitDisconnects: Waiting for node disconnection completion2019-10-30 20:01:18.602+0000 [id=155008] INFO jenkins.model.Jenkins#cleanUp: Jenkins stopped2019-10-30 20:01:22.820+0000 [id=151613] WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.2019-10-30 20:01:27.573+0000 [id=152096] WARNING o.e.jetty.server.HttpChannel#handleException: /tcpSlaveAgentListener/java.lang.IllegalStateException: Jenkins.instance is missing. Read the documentation of Jenkins.getInstanceOrNull to see what you are doing wrong. at jenkins.model.Jenkins.get(Jenkins.java:777) at org.jenkinsci.plugins.matrixauth.AuthorizationContainer.hasPermission(AuthorizationContainer.java:169) at hudson.security.GlobalMatrixAuthorizationStrategy$AclImpl.hasPermission(GlobalMatrixAuthorizationStrategy.java:127) at hudson.security.SidACL._hasPermission(SidACL.java:70) at hudson.security.SidACL.hasPermission(SidACL.java:52) at hudson.security.ACL.checkPermission(ACL.java:72) at hudson.security.AccessControlled.checkPermission(AccessControlled.java:47) at jenkins.model.Jenkins.getTarget(Jenkins.java:4763) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:703) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:878) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:676) at hudson.init.impl.InstallUncaughtExceptionHandler.lambda$init$0(InstallUncaughtExceptionHandler.java:36) at org.kohsuke.stapler.compression.CompressionFilter.reportException(CompressionFilter.java:77) at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:58) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:505) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804) at java.lang.Thread.run(Unknown Source)

 

 

Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.13.6#713006-sha1:cc4451f)
Atlassian logo

wfollonier@cloudbees.com (JIRA)

unread,
Oct 31, 2019, 5:07:03 AM10/31/19
to jenkinsc...@googlegroups.com
Wadeck Follonier updated an issue
Change By: Wadeck Follonier
Auto-Upgrade Jenkins, select Restart Jenkins when complete...

Manual restart via https://<jenkins>/restart...

 

Logs (see below) show shutdown and restart occurs. However, during startup, an infinite cycle of exceptions (Jenkins.instance is missing) see below. Must manually restart windows service to successfully restart jenkins.

 
{code:java}
2019-10-30 19:58:18.332+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Starting the installation of jenkins.war on behalf of
xxxxx2019 xxxxx
2019
-10-30 19:58:18.332+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Starting the installation of jenkins.war on behalf of xxxxx2019 xxxxx
2019
-10-30 19:58:18.532+0000 [id=154905] INFO h.m.UpdateCenter$UpdateCenterConfiguration#download: Downloading jenkins. war2019 war
2019
-10-30 19:58:23.497+0000 [id=154905] INFO h.model.UpdateCenter$DownloadJob#run: Installation successful: jenkins. war2019 war
2019
-10-30 20:01:07.466+0000 [id=151608] INFO hudson.model.UpdateCenter#doSafeRestart: Scheduling Jenkins reboot2019 reboot
2019
-10-30 20:01:07.478+0000 [id=155008] INFO jenkins.model.Jenkins$23#run: Restart in 10 seconds2019 seconds
2019
-10-30 20:01:17.479+0000 [id=155008] INFO jenkins.model.Jenkins$23#run: Restarting VM as requested by xxxxx2019 xxxxx
2019
-10-30 20:01:17.481+0000 [id=155008] INFO jenkins.model.Jenkins#cleanUp: Stopping Jenkins2019 Jenkins
2019
-10-30 20:01:17.529+0000 [id=155008] INFO jenkins.model.Jenkins$18#onAttained: Started termination2019 termination
2019
-10-30 20:01:17.542+0000 [id=155008] INFO jenkins.model.Jenkins$18#onAttained: Completed termination2019 termination
2019
-10-30 20:01:17.542+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection2019 disconnection
2019
-10-30 20:01:17.550+0000 [id=155008] INFO j.s.DefaultJnlpSlaveReceiver#channelClosed: safe-restart thread for xxxx terminated: java.nio.channels. ClosedChannelException2019 ClosedChannelException
2019
-10-30 20:01:17.557+0000 [id=155008] INFO j.s.DefaultJnlpSlaveReceiver#channelClosed: safe-restart thread for xxxx terminated: java.nio.channels. ClosedChannelException2019 ClosedChannelException
2019
-10-30 20:01:18.569+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager2019 manager
2019
-10-30 20:01:18.596+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue2019 queue
2019
-10-30 20:01:18.602+0000 [id=155008] INFO jenkins.model.Jenkins#_cleanUpAwaitDisconnects: Waiting for node disconnection completion2019 completion
2019
-10-30 20:01:18.602+0000 [id=155008] INFO jenkins.model.Jenkins#cleanUp: Jenkins stopped2019 stopped
2019
-10-30 20:01:22.820+0000 [id=151613] WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.
at java.lang.Thread.run(Unknown Source)
{code}
 

 

wfollonier@cloudbees.com (JIRA)

unread,
Oct 31, 2019, 7:24:03 AM10/31/19
to jenkinsc...@googlegroups.com
Wadeck Follonier commented on Bug JENKINS-59992
 
Re: "Jenkins.instance is missing" error when restarting Jenkins

Thank you Craig Lutgen for the report. Due to the stack trace, the symptoms are different from JENKINS-55070. Here the problem is revealed in AuthorizationContainer.java#L169.

After a deeper investigation, the problem seems to be after the nullification of theInstance in Jenkins#L3400. There is a moment between the instance being null and the real restart (fraction of second) and that that time, the instance cannot be retrieved.

As the HudsonIsRestarting is only used as the last filter, it has no chance to avoid other computation yet. The problem is when a filter that is applied earlier, requires to have access to Jenkins.get().

I see two opportunities to correct the problem:

  1. Ensure every filter or class being potentially used by a filter, to not use Jenkins.get(), but instead Jenkins.getInstanceOrNull() and act correctly in case it's null. This could require a lots of work and hard time explaining the situation to people.
  2. Prevent the regular filters to be applied when the HudsonIsRestarting is the "app" in the servletContext.

To elaborate on option 2, current flow of filters to servlet:

  • DiagnosticThreadNameFilter
  • CharacterEncodingFilter
  • CompressionFilter
  • HudsonFilter
    • ChainedServletFilter
      • HttpSessionContextIntegrationFilter2
      • BasicHeaderProcessor
      • AuthenticationProcessingFilter2
      • RememberMeProcessingFilter
      • AnonymousProcessingFilter
      • ExceptionTranslationFilter
      • UnwrapSecurityExceptionFilter
    • CrumbFilter
    • PluginServletFilter
      • UserLanguages
      • [...] << PluginServletFilter.addFilter (mainly for legacy plugins)
  • Stapler as the main Servlet

We could either bypass completely the filter and reach directly the app, or disabling the configured filters. If we bypass the rest of the filter, we will have troubles to deliver the asset bounded to the restart page, but this could be done "inline" and avoid any other parallel call.

That could solve the

> WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.

But I was not able to reproduce the second warning, as I was not using the WindowsService. I imagine it's somewhat linked.

wfollonier@cloudbees.com (JIRA)

unread,
Oct 31, 2019, 7:25:02 AM10/31/19
to jenkinsc...@googlegroups.com
Wadeck Follonier edited a comment on Bug JENKINS-59992
Thank you [~csclutgen] for the report. Due to the stack trace, the symptoms are different from JENKINS-55070. Here the problem is revealed in [AuthorizationContainer.java#L169|https://github.com/jenkinsci/matrix-auth-plugin/blob/master/src/main/java/org/jenkinsci/plugins/matrixauth/AuthorizationContainer.java#L169].

After a deeper investigation, the problem seems to be after the nullification of {{theInstance}} in [Jenkins#L3400|https://github.com/jenkinsci/jenkins/blob/06f4c89121533fd669a102c97b514534ef1ebcb7/core/src/main/java/jenkins/model/Jenkins.java#L3400-L3404]. There is a moment between the instance being null and the real restart (fraction of second) and that that time, the instance cannot be retrieved.

As the HudsonIsRestarting is only used as the last filter, it has no chance to avoid other computation yet. The problem is when a filter that is applied earlier, requires to have access to {{Jenkins.get()}}.


I see two opportunities to correct the problem:
# Ensure every filter or class being potentially used by a filter, to not use {{Jenkins.get()}}, but instead {{Jenkins.getInstanceOrNull()}} and act correctly in case it's null. This could require a lots of work and hard time explaining the situation to people.
# Prevent the regular filters to be applied when the HudsonIsRestarting is the "app" in the servletContext.

To elaborate on option 2, current flow of filters to servlet:
*  DiagnosticThreadNameFilter
*  CharacterEncodingFilter
*  CompressionFilter
*  HudsonFilter
**   ChainedServletFilter
***   HttpSessionContextIntegrationFilter2
***   BasicHeaderProcessor
***   AuthenticationProcessingFilter2
***   RememberMeProcessingFilter
***   AnonymousProcessingFilter
***   ExceptionTranslationFilter
***   UnwrapSecurityExceptionFilter
** CrumbFilter
** PluginServletFilter
***  UserLanguages
***  [...] << PluginServletFilter.addFilter (mainly for legacy plugins)
* Stapler as the main Servlet

We could either bypass completely the
filter filters (HudsonFilter + CrumbFilter + PluginServletFilter) and reach directly the app (Stapler) , or disabling the configured filters. If we bypass the rest of the filter, we will have troubles to deliver the asset bounded to the restart page, but this could be done "inline" and avoid any other parallel call.

That could solve the
> WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.

But I was not able to reproduce the second warning, as I was not using the WindowsService. I imagine it's somewhat linked.

wfollonier@cloudbees.com (JIRA)

unread,
Oct 31, 2019, 11:23:04 AM10/31/19
to jenkinsc...@googlegroups.com
  UserLanguages
**
*   [...] << PluginServletFilter.addFilter (mainly for legacy plugins)

* Stapler as the main Servlet

We could either bypass completely the filters (HudsonFilter + CrumbFilter + PluginServletFilter) and reach directly the app (Stapler), or disabling the configured filters. If we bypass the rest of the filter, we will have troubles to deliver the asset bounded to the restart page, but this could be done "inline" and avoid any other parallel call.

That could solve the
> WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.

But I was not able to reproduce the second warning, as I was not using the WindowsService. I imagine it's somewhat linked.

o.v.nenashev@gmail.com (JIRA)

unread,
Nov 10, 2019, 6:34:03 PM11/10/19
to jenkinsc...@googlegroups.com

o.v.nenashev@gmail.com (JIRA)

unread,
Nov 10, 2019, 6:34:04 PM11/10/19
to jenkinsc...@googlegroups.com

dbeck@cloudbees.com (JIRA)

unread,
Nov 11, 2019, 5:07:04 AM11/11/19
to jenkinsc...@googlegroups.com
Daniel Beck assigned an issue to Unassigned
Change By: Daniel Beck
Assignee: Daniel Beck

dbeck@cloudbees.com (JIRA)

unread,
Nov 11, 2019, 5:07:05 AM11/11/19
to jenkinsc...@googlegroups.com
Daniel Beck updated an issue
Change By: Daniel Beck
Component/s: matrix-auth-plugin

wfollonier@cloudbees.com (JIRA)

unread,
Jan 13, 2020, 3:10:03 AM1/13/20
to jenkinsc...@googlegroups.com
Wadeck Follonier edited a comment on Bug JENKINS-59992
Thank you [~csclutgen] for the report. Due to the stack trace, the symptoms are different from JENKINS-55070. Here the problem is revealed in [AuthorizationContainer.java#L169|https://github.com/jenkinsci/matrix-auth-plugin/blob/master/src/main/java/org/jenkinsci/plugins/matrixauth/AuthorizationContainer.java#L169].

After a deeper investigation, the problem seems to be after the nullification of {{theInstance}} in [Jenkins#L3400|https://github.com/jenkinsci/jenkins/blob/06f4c89121533fd669a102c97b514534ef1ebcb7/core/src/main/java/jenkins/model/Jenkins.java#L3400-L3404]. There is a moment between the instance being null and the real restart (fraction of second) and during that that time, the instance cannot be retrieved.


As the HudsonIsRestarting is only used as the last filter, it has no chance to avoid other computation yet. The problem is when a filter that is applied earlier, requires to have access to {{Jenkins.get()}}.

I see two opportunities to correct the problem:
# Ensure every filter or class being potentially used by a filter, to not use {{Jenkins.get()}}, but instead {{Jenkins.getInstanceOrNull()}} and act correctly in case it's null. This could require a lots of work and hard time explaining the situation to people.
# Prevent the regular filters to be applied when the HudsonIsRestarting is the "app" in the servletContext.

To elaborate on option 2, current flow of filters to servlet:
*  DiagnosticThreadNameFilter
*  CharacterEncodingFilter
*  CompressionFilter
*  HudsonFilter
**   ChainedServletFilter
***   HttpSessionContextIntegrationFilter2
***   BasicHeaderProcessor
***   AuthenticationProcessingFilter2
***   RememberMeProcessingFilter
***   AnonymousProcessingFilter
***   ExceptionTranslationFilter
***   UnwrapSecurityExceptionFilter
* CrumbFilter
* PluginServletFilter
**  UserLanguages
**  [...] << PluginServletFilter.addFilter (mainly for legacy plugins)

* Stapler as the main Servlet

We could either bypass completely the filters (HudsonFilter + CrumbFilter + PluginServletFilter) and reach directly the app (Stapler), or disabling the configured filters. If we bypass the rest of the filter, we will have troubles to deliver the asset bounded to the restart page, but this could be done "inline" and avoid any other parallel call.

That could solve the
> WARNING h.s.HttpSessionContextIntegrationFilter2#hasInvalidSessionSeed: Encountered IllegalStateException trying to get a user. System init may not have completed yet. Invalidating user session.

But I was not able to reproduce the second warning, as I was not using the WindowsService. I imagine it's somewhat linked.

wfollonier@cloudbees.com (JIRA)

unread,
Feb 25, 2020, 8:11:03 AM2/25/20
to jenkinsc...@googlegroups.com
Wadeck Follonier started work on Bug JENKINS-59992
 
Change By: Wadeck Follonier
Status: Open In Progress

wfollonier@cloudbees.com (JIRA)

unread,
Feb 25, 2020, 8:11:03 AM2/25/20
to jenkinsc...@googlegroups.com

wfollonier@cloudbees.com (JIRA)

unread,
Feb 25, 2020, 8:12:09 AM2/25/20
to jenkinsc...@googlegroups.com

wfollonier@cloudbees.com (JIRA)

unread,
Feb 25, 2020, 8:12:11 AM2/25/20
to jenkinsc...@googlegroups.com

wfollonier@cloudbees.com (JIRA)

unread,
Apr 21, 2020, 2:51:07 AM4/21/20
to jenkinsc...@googlegroups.com
 

Symptoms resolved in 2.223

Change By: Wadeck Follonier
Status: In Review Closed
Resolution: Fixed
Released As: 2.223
This message was sent by Atlassian Jira (v7.13.12#713012-sha1:6e07c38)
Atlassian logo
Reply all
Reply to author
Forward
0 new messages