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

ClassNotFoundException: hudson.model.job

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Component/s: core
    • Labels:
      None
    • Environment:
      seen on Hudson 1.331 or newer running with IBM JVM

      Description

      Every once in a while with Hudson v1.337 we get the following stack trace:

      org.apache.commons.jelly.JellyTagException: jar:file:/opt/users/hudsonbuild/.hudson/war/WEB-INF/lib/hudson-core-1.337.jar!/hudson/widgets/HistoryWidget/index.jelly:28:81: method forName threw exception: hudson.model.Job
      at org.apache.commons.jelly.tags.core.InvokeStaticTag.doTag(InvokeStaticTag.java:148)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.ParseTag.parseBody(ParseTag.java:178)
      at org.apache.commons.jelly.tags.core.ParseTag.doTag(ParseTag.java:78)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.JellyTag.doTag(JellyTag.java:45)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:118)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:150)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.kohsuke.stapler.jelly.CustomTagLibrary$StaplerDynamicTag$1.run(CustomTagLibrary.java:147)
      at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.IfTag.doTag(IfTag.java:42)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.JellyTag.doTag(JellyTag.java:45)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.DynamicTag.doTag(DynamicTag.java:81)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.JellyTag.doTag(JellyTag.java:45)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:118)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.kohsuke.stapler.jelly.CustomTagLibrary$StaplerDynamicTag$1.run(CustomTagLibrary.java:147)
      at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.impl.StaticTag.doTag(StaticTag.java:65)
      at org.apache.commons.jelly.impl.StaticTagScript.run(StaticTagScript.java:112)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.JellyTag.doTag(JellyTag.java:45)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.DynamicTag.doTag(DynamicTag.java:81)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
      at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:186)
      at org.apache.commons.jelly.tags.core.JellyTag.doTag(JellyTag.java:45)
      at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:262)
      at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:29)
      at org.kohsuke.stapler.jelly.JellyClassTearOff.serveIndexJelly(JellyClassTearOff.java:43)
      at org.kohsuke.stapler.jelly.JellyFacet.handleIndexRequest(JellyFacet.java:83)
      at org.kohsuke.stapler.Stapler.invoke(Stapler.java:481)
      at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:180)
      at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:30)
      at org.kohsuke.stapler.Stapler.invoke(Stapler.java:492)
      at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:180)
      at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:30)
      at org.kohsuke.stapler.Stapler.invoke(Stapler.java:492)
      at org.kohsuke.stapler.Stapler.invoke(Stapler.java:408)
      at org.kohsuke.stapler.Stapler.service(Stapler.java:117)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:45)
      at winstone.ServletConfiguration.execute(ServletConfiguration.java:249)
      at winstone.RequestDispatcher.forward(RequestDispatcher.java:335)
      at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:378)
      at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:94)
      at org.jvnet.hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:47)
      at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:97)
      at hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:64)
      at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:97)
      at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:86)
      at winstone.FilterConfiguration.execute(FilterConfiguration.java:195)
      at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:368)
      at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:47)
      at winstone.FilterConfiguration.execute(FilterConfiguration.java:195)
      at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:368)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:84)
      at hudson.security.UnwrapSecurityExceptionFilter.doFilter(UnwrapSecurityExceptionFilter.java:51)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.ui.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:166)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.providers.anonymous.AnonymousProcessingFilter.doFilter(AnonymousProcessingFilter.java:125)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.ui.rememberme.RememberMeProcessingFilter.doFilter(RememberMeProcessingFilter.java:142)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:271)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.ui.basicauth.BasicProcessingFilter.doFilter(BasicProcessingFilter.java:173)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249)
      at hudson.security.HttpSessionContextIntegrationFilter2.doFilter(HttpSessionContextIntegrationFilter2.java:66)
      at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
      at hudson.security.ChainedServletFilter.doFilter(ChainedServletFilter.java:76)
      at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:164)
      at winstone.FilterConfiguration.execute(FilterConfiguration.java:195)
      at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:368)
      at winstone.RequestDispatcher.forward(RequestDispatcher.java:333)
      at winstone.RequestHandlerThread.processRequest(RequestHandlerThread.java:244)
      at winstone.RequestHandlerThread.run(RequestHandlerThread.java:150)
      at java.lang.Thread.run(Thread.java:810)
      Caused by: java.lang.ClassNotFoundException: hudson.model.Job
      at java.lang.Class.forNameImpl(Native Method)
      at java.lang.Class.forName(Class.java:130)
      at sun.reflect.GeneratedMethodAccessor1117.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:618)
      at org.apache.commons.jelly.tags.core.InvokeStaticTag.doTag(InvokeStaticTag.java:125)
      ... 125 more

      A restart of the system makes it disappear for a time, but it eventually reoccurs.

        Activity

        Hide
        kingargyle kingargyle added a comment -

        We consistently get this as documented in this long standing Eclipse bug:

        https://bugs.eclipse.org/bugs/show_bug.cgi?id=305675

        Also, this seemed to start and continues to happen as we add Slave machines to the Master system. I do not remember seeing this situation occuring when there were no slaves involved.

        Show
        kingargyle kingargyle added a comment - We consistently get this as documented in this long standing Eclipse bug: https://bugs.eclipse.org/bugs/show_bug.cgi?id=305675 Also, this seemed to start and continues to happen as we add Slave machines to the Master system. I do not remember seeing this situation occuring when there were no slaves involved.
        Hide
        bartlejd bartlejd added a comment -

        I've found a way to reproduce and a way to work around and now I
        have a way to fix the problem.

        The following one-line script can be used to reproduce at will.
        Just replace the bits in brackets with values to match the hudson
        instance under test. In my testing it usually fails after just
        over 1,000 iterations, less than 2 minutes:

        count=0;time while [ $

        {count} -lt 2000 ];do echo ${count}

        ;curl http://<hostname>:<portnumber>/job/<someJobName>/ | grep -i Exception;if [ $? -eq 0 ];then break;fi; (( count = count + 1 ));done

        The problem can be worked around by using the following jvm
        argument:

        -Xjit:

        {sun/reflect/GeneratedMethodAccessor*.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;}

        (disableInlining)

        I've created a fork of the hudson git repository on github that has my patches
        to fix the problem ( http://github.com/bartleyj/hudson ). I can also post them
        here if that's preferred.

        Ultimately, this is a defect in the jvm and I have opened a bug against IBM's
        implementation to have it fixed there, but it can be worked around in hudson
        code pretty easily. Bear in mind that I have not yet had my reasoning confirmed
        by IBM JVM support, but I think it holds up. So let me explain what's going on
        as I see it.

        There are 2 jelly files involved:

        core/src/main/resources/hudson/model/ParametersAction/index.jelly
        and
        core/src/main/resources/hudson/widgets/HistoryWidget/index.jelly

        These jelly files are trying to call Class.forName(String) to load some class (
        hudson.model.Job and hudson.model.AbstractBuild ). Class.forName(String) does
        not take a ClassLoader as an argument so it has to figure out the right one to
        use. It does this by making recourse to a native method that sniffs the stack
        looking for the caller's Class and it's associated ClassLoader. It does this
        by looking out 2 frames ( hard-coded ) from the current point in the stack.
        Because jelly is an interpreted environment, it has to invoke Class.forName via
        reflection, which adds stack frames to the stack trace. I'm guessing that the
        native method looks for sun/reflect/GeneratedMethodAccessor*.invoke to detect
        when it's being called via reflection so it can discount those frames in
        counting down 2. But after the jvm has been running for some time, the JIT
        decides that precisely those methods are being used enough to warrant inlining
        so suddenly they no longer appear in the stack and so the wrong stack frame
        starts getting picked out of the stack trace. Instead of settling on the
        webapp classloader it's getting the boot classloader which can't see anything
        in hudson's domain and thus we suffer a ClassNotFoundException.

        My fix to hudson modifies the jelly files to look up the context classloader
        from the current thread instead of relying on Class.forName. Chalk up another
        reason to avoid Class.forName.

        Show
        bartlejd bartlejd added a comment - I've found a way to reproduce and a way to work around and now I have a way to fix the problem. The following one-line script can be used to reproduce at will. Just replace the bits in brackets with values to match the hudson instance under test. In my testing it usually fails after just over 1,000 iterations, less than 2 minutes: count=0;time while [ $ {count} -lt 2000 ];do echo ${count} ;curl http://<hostname>:<portnumber>/job/<someJobName>/ | grep -i Exception;if [ $? -eq 0 ];then break;fi; (( count = count + 1 ));done The problem can be worked around by using the following jvm argument: -Xjit: {sun/reflect/GeneratedMethodAccessor*.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;} (disableInlining) I've created a fork of the hudson git repository on github that has my patches to fix the problem ( http://github.com/bartleyj/hudson ). I can also post them here if that's preferred. Ultimately, this is a defect in the jvm and I have opened a bug against IBM's implementation to have it fixed there, but it can be worked around in hudson code pretty easily. Bear in mind that I have not yet had my reasoning confirmed by IBM JVM support, but I think it holds up. So let me explain what's going on as I see it. There are 2 jelly files involved: core/src/main/resources/hudson/model/ParametersAction/index.jelly and core/src/main/resources/hudson/widgets/HistoryWidget/index.jelly These jelly files are trying to call Class.forName(String) to load some class ( hudson.model.Job and hudson.model.AbstractBuild ). Class.forName(String) does not take a ClassLoader as an argument so it has to figure out the right one to use. It does this by making recourse to a native method that sniffs the stack looking for the caller's Class and it's associated ClassLoader. It does this by looking out 2 frames ( hard-coded ) from the current point in the stack. Because jelly is an interpreted environment, it has to invoke Class.forName via reflection, which adds stack frames to the stack trace. I'm guessing that the native method looks for sun/reflect/GeneratedMethodAccessor*.invoke to detect when it's being called via reflection so it can discount those frames in counting down 2. But after the jvm has been running for some time, the JIT decides that precisely those methods are being used enough to warrant inlining so suddenly they no longer appear in the stack and so the wrong stack frame starts getting picked out of the stack trace. Instead of settling on the webapp classloader it's getting the boot classloader which can't see anything in hudson's domain and thus we suffer a ClassNotFoundException. My fix to hudson modifies the jelly files to look up the context classloader from the current thread instead of relying on Class.forName. Chalk up another reason to avoid Class.forName.
        Hide
        mindless Alan Harder added a comment -

        bartlejd, thanks for the detailed investigation and report!
        I found one copy/paste error in the patch ("buildClass" became "jobClass") but otherwise looks good.. I'll apply and commit it.

        Show
        mindless Alan Harder added a comment - bartlejd, thanks for the detailed investigation and report! I found one copy/paste error in the patch ("buildClass" became "jobClass") but otherwise looks good.. I'll apply and commit it.
        Hide
        scm_issue_link SCM/JIRA link daemon added a comment -

        Code changed in hudson
        User: : mindless
        Path:
        trunk/hudson/main/core/src/main/resources/hudson/model/ParametersAction/index.jelly
        trunk/hudson/main/core/src/main/resources/hudson/widgets/HistoryWidget/index.jelly
        trunk/www/changelog.html
        http://jenkins-ci.org/commit/33546
        Log:
        [FIXED JENKINS-5141] workaround issue in IBM JVM causing intermittent
        ClassNotFoundException by using thread contextClassLoader in jellies
        instead of Class.forName(). Detailed description and patch suggestion
        from bartlejd in JENKINS-5141.

        Show
        scm_issue_link SCM/JIRA link daemon added a comment - Code changed in hudson User: : mindless Path: trunk/hudson/main/core/src/main/resources/hudson/model/ParametersAction/index.jelly trunk/hudson/main/core/src/main/resources/hudson/widgets/HistoryWidget/index.jelly trunk/www/changelog.html http://jenkins-ci.org/commit/33546 Log: [FIXED JENKINS-5141] workaround issue in IBM JVM causing intermittent ClassNotFoundException by using thread contextClassLoader in jellies instead of Class.forName(). Detailed description and patch suggestion from bartlejd in JENKINS-5141 .
        Hide
        scm_issue_link SCM/JIRA link daemon added a comment -

        Code changed in hudson
        User: : mindless
        Path:
        trunk/hudson/plugins/jobrevision/src/main/resources/com/thalesgroup/hudson/plugins/jobrevision/RevisionResult/index.jelly
        http://jenkins-ci.org/commit/33547
        Log:
        [jobrevision] apply same change made in Hudson core for JENKINS-5141

        Show
        scm_issue_link SCM/JIRA link daemon added a comment - Code changed in hudson User: : mindless Path: trunk/hudson/plugins/jobrevision/src/main/resources/com/thalesgroup/hudson/plugins/jobrevision/RevisionResult/index.jelly http://jenkins-ci.org/commit/33547 Log: [jobrevision] apply same change made in Hudson core for JENKINS-5141

          People

          • Assignee:
            bartlejd bartlejd
            Reporter:
            kingargyle kingargyle
          • Votes:
            2 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: