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

race condition in CrumbFilter and CrumbIssuer

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Minor Minor
    • core
    • None

      At startup you will often see (if the machine is slow enough?)
      lots of exceptions due to class hudson.security.csrf.DefaultCrumbIssuer is missing its descriptor if the web interface is hit.

      this is because the CrumbFilter is installed before Jenkins is fully up - and Jenkins now has its crumb issuer set before plugins and extensions have been found and loaded.

      Aug 12, 2020 3:09:32 PM org.jenkinsci.test.acceptance.controller.LocalController startNow
      INFO: Waiting for Jenkins to become running in http://192.168.147.189:52941/
      master52941|Running from: C:\workarea\source\github\cloudbees\je-acceptance-test\jenkins.war
      master52941|webroot: EnvVars.masterEnvVars.get("JENKINS_HOME")
      master52941|2020-08-12 14:09:33.297+0000 [id=1] INFO    org.eclipse.jetty.util.log.Log#initialized: Logging initialized @1082ms to org.eclipse.jetty.util.log.JavaUtilLog
      master52941|2020-08-12 14:09:33.435+0000 [id=1] INFO    winstone.Logger#logInternal: Beginning extraction from war file
      master52941|2020-08-12 14:09:33.480+0000 [id=1] WARNING o.e.j.s.handler.ContextHandler#setContextPath: Empty contextPath
      master52941|2020-08-12 14:09:33.553+0000 [id=1] INFO    org.eclipse.jetty.server.Server#doStart: jetty-9.4.27.v20200227; built: 2020-02-27T18:37:21.340Z; git: a304fd9f351f337e7c0e2a7c28878dd536149c6c; jvm 1.8.0_221-b11
      master52941|2020-08-12 14:09:34.592+0000 [id=1] INFO    o.e.j.w.StandardDescriptorProcessor#visitServlet: NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
      master52941|2020-08-12 14:09:34.704+0000 [id=1] INFO    o.e.j.s.s.DefaultSessionIdManager#doStart: DefaultSessionIdManager workerName=node0
      master52941|2020-08-12 14:09:34.704+0000 [id=1] INFO    o.e.j.s.s.DefaultSessionIdManager#doStart: No SessionScavenger set, using defaults
      master52941|2020-08-12 14:09:34.710+0000 [id=1] INFO    o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms
      master52941|2020-08-12 14:09:35.270+0000 [id=1] INFO    hudson.WebAppMain#contextInitialized: Jenkins home directory: C:\workarea\source\github\cloudbees\je-acceptance-test\target\jenkins2696073748183544465home found at: EnvVars.masterEnvVars.get("JENKINS_HOME")
      master52941|2020-08-12 14:09:35.413+0000 [id=1] INFO    o.e.j.s.handler.ContextHandler#doStart: Started w.@730d2164{CloudBees Jenkins Distribution,/,file:///C:/workarea/source/github/cloudbees/je-acceptance-test/target/jenkins2696073748183544465home/war/,AVAILABLE}{C:\workarea\source\github\cloudbees\je-acceptance-test\target\jenkins2696073748183544465home\war}
      master52941|2020-08-12 14:09:35.448+0000 [id=1] INFO    o.e.j.server.AbstractConnector#doStart: Started ServerConnector@3fb6a447{HTTP/1.1, (http/1.1)}{0.0.0.0:52941}
      master52941|2020-08-12 14:09:35.448+0000 [id=1] INFO    org.eclipse.jetty.server.Server#doStart: Started @3233ms
      master52941|2020-08-12 14:09:35.449+0000 [id=23]        INFO    winstone.Logger#logInternal: Winstone Servlet Engine running: controlPort=disabled
      master52941|2020-08-12 14:09:37.115+0000 [id=32]        INFO    jenkins.InitReactorRunner$1#onAttained: Started initialization
      master52941|2020-08-12 14:09:37.915+0000 [id=35]        INFO    jenkins.InitReactorRunner$1#onAttained: Listed all plugins
      master52941|2020-08-12 14:09:38.363+0000 [id=29]        WARNING h.i.i.InstallUncaughtExceptionHandler#handleException: Caught unhandled exception with ID 6e561e26-f811-473c-b5dd-7710fb0b2b7e
      master52941|java.lang.AssertionError: class hudson.security.csrf.DefaultCrumbIssuer is missing its descriptor
      master52941|    at jenkins.model.Jenkins.getDescriptorOrDie(Jenkins.java:1600)
      master52941|    at hudson.security.csrf.CrumbIssuer.getDescriptor(CrumbIssuer.java:152)
      master52941|    at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:131)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:169)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at jenkins.security.SuspiciousRequestFilter.doFilter(SuspiciousRequestFilter.java:36)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      master52941|    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:566)
      master52941|    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
      master52941|    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
      master52941|    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
      master52941|    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
      master52941|    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      master52941|    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      master52941|    at org.eclipse.jetty.server.Server.handle(Server.java:500)
      master52941|    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
      master52941|    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
      master52941|    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
      master52941|    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
      master52941|    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
      master52941|    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
      master52941|    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
      master52941|    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
      master52941|    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
      master52941|    at java.lang.Thread.run(Thread.java:748)
      master52941|2020-08-12 14:09:38.363+0000 [id=18]        WARNING h.i.i.InstallUncaughtExceptionHandler#handleException: Caught unhandled exception with ID 6700fc9f-bba6-4a59-b02e-f77aa8ba93d2
      master52941|java.lang.AssertionError: class hudson.security.csrf.DefaultCrumbIssuer is missing its descriptor
      master52941|    at jenkins.model.Jenkins.getDescriptorOrDie(Jenkins.java:1600)
      master52941|    at hudson.security.csrf.CrumbIssuer.getDescriptor(CrumbIssuer.java:152)
      master52941|    at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:131)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:169)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at jenkins.security.SuspiciousRequestFilter.doFilter(SuspiciousRequestFilter.java:36)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      master52941|    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:566)
      master52941|    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
      master52941|    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
      master52941|    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
      master52941|    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
      master52941|    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
      master52941|    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
      master52941|    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      master52941|    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      master52941|    at org.eclipse.jetty.server.Server.handle(Server.java:500)
      master52941|    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
      master52941|    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
      master52941|    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
      master52941|    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
      master52941|    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
      master52941|    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
      master52941|    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
      master52941|    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
      master52941|    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
      master52941|    at java.lang.Thread.run(Thread.java:748)
      master52941|2020-08-12 14:09:43.549+0000 [id=43]        INFO    jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
      master52941|2020-08-12 14:09:44.371+0000 [id=36]        INFO    jenkins.InitReactorRunner$1#onAttained: Started all plugins
      master52941|2020-08-12 14:09:44.384+0000 [id=45]        INFO    jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
      master52941|2020-08-12 14:09:44.527+0000 [id=30]        INFO    jenkins.InitReactorRunner$1#onAttained: System config loaded
      master52941|2020-08-12 14:09:45.984+0000 [id=30]        INFO    jenkins.InitReactorRunner$1#onAttained: System config adapted
      master52941|2020-08-12 14:09:45.984+0000 [id=36]        INFO    jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
      master52941|2020-08-12 14:09:45.984+0000 [id=44]        INFO    jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
      

      best guess is a regression caused by putting a default crumb issuer in Jenkins which will be available before extensions

      https://github.com/jenkinsci/jenkins/commit/107c8575a426784be07e9f29170da4c385a17e59#r41410904

            Unassigned Unassigned
            teilo James Nord
            Votes:
            26 Vote for this issue
            Watchers:
            41 Start watching this issue

              Created:
              Updated: