Bug 62757

Summary: JspCompilationContext is unable to compile class for JSP due to a null tagHandlerClass in Generator.TagHandlerInfo
Product: Tomcat 8 Reporter: Jordi Llach <jllachf>
Component: JasperAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: regression CC: julien
Priority: P2    
Version: 8.5.33   
Target Milestone: ----   
Hardware: All   
OS: All   
Attachments: patch for the reported bug
Alternative patch

Description Jordi Llach 2018-09-25 19:02:29 UTC
I am still debuging in order to try understand the reason for this, and improve the issue description.
The app behaviour is :
- launch tomcat 
- access a jsp which depends on several nested tags(all of them need to be compiled)
- it takes several reloads to render the jsp as expected, failing with the following exception the rest of the times

HTTP Status 500 – Internal Server Error
Type Exception Report

Message Unable to compile class for JSP

Description The server encountered an unexpected condition that prevented it from fulfilling the request.

Exception

org.apache.jasper.JasperException: Unable to compile class for JSP
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:611)
	org.apache.jasper.servlet.JspServletWrapper.loadTagFile(JspServletWrapper.java:262)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFile(TagFileProcessor.java:585)
	org.apache.jasper.compiler.TagFileProcessor.access$000(TagFileProcessor.java:48)
	org.apache.jasper.compiler.TagFileProcessor$TagFileLoaderVisitor.visit(TagFileProcessor.java:668)
	org.apache.jasper.compiler.Node$CustomTag.accept(Node.java:1544)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Node$Visitor.visitBody(Node.java:2441)
	org.apache.jasper.compiler.Node$Visitor.visit(Node.java:2447)
	org.apache.jasper.compiler.Node$Root.accept(Node.java:470)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFiles(TagFileProcessor.java:691)
	org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:232)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:373)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:350)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:334)
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:595)
	org.apache.jasper.servlet.JspServletWrapper.loadTagFile(JspServletWrapper.java:262)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFile(TagFileProcessor.java:585)
	org.apache.jasper.compiler.TagFileProcessor.access$000(TagFileProcessor.java:48)
	org.apache.jasper.compiler.TagFileProcessor$TagFileLoaderVisitor.visit(TagFileProcessor.java:668)
	org.apache.jasper.compiler.Node$CustomTag.accept(Node.java:1544)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Node$Visitor.visitBody(Node.java:2441)
	org.apache.jasper.compiler.Node$Visitor.visit(Node.java:2447)
	org.apache.jasper.compiler.Node$Root.accept(Node.java:470)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFiles(TagFileProcessor.java:691)
	org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:232)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:373)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:350)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:334)
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:595)
	org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:382)
	org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
	<omiting spring framework stack>
Root Cause

java.lang.NullPointerException
	sun.reflect.misc.ReflectUtil.checkPackageAccess(ReflectUtil.java:164)
	sun.reflect.misc.ReflectUtil.isPackageAccessible(ReflectUtil.java:195)
	java.beans.Introspector.getBeanInfo(Introspector.java:164)
	org.apache.jasper.compiler.Generator$TagHandlerInfo.<init>(Generator.java:4115)
	org.apache.jasper.compiler.Generator$GenerateVisitor.getTagHandlerInfo(Generator.java:2349)
	org.apache.jasper.compiler.Generator$GenerateVisitor.visit(Generator.java:1782)
	org.apache.jasper.compiler.Node$CustomTag.accept(Node.java:1544)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Node$Visitor.visitBody(Node.java:2441)
	org.apache.jasper.compiler.Node$Visitor.visit(Node.java:2447)
	org.apache.jasper.compiler.Node$Root.accept(Node.java:470)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Generator.generate(Generator.java:3653)
	org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:253)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:373)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:350)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:334)
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:595)
	org.apache.jasper.servlet.JspServletWrapper.loadTagFile(JspServletWrapper.java:262)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFile(TagFileProcessor.java:585)
	org.apache.jasper.compiler.TagFileProcessor.access$000(TagFileProcessor.java:48)
	org.apache.jasper.compiler.TagFileProcessor$TagFileLoaderVisitor.visit(TagFileProcessor.java:668)
	org.apache.jasper.compiler.Node$CustomTag.accept(Node.java:1544)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Node$Visitor.visitBody(Node.java:2441)
	org.apache.jasper.compiler.Node$Visitor.visit(Node.java:2447)
	org.apache.jasper.compiler.Node$Root.accept(Node.java:470)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFiles(TagFileProcessor.java:691)
	org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:232)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:373)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:350)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:334)
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:595)
	org.apache.jasper.servlet.JspServletWrapper.loadTagFile(JspServletWrapper.java:262)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFile(TagFileProcessor.java:585)
	org.apache.jasper.compiler.TagFileProcessor.access$000(TagFileProcessor.java:48)
	org.apache.jasper.compiler.TagFileProcessor$TagFileLoaderVisitor.visit(TagFileProcessor.java:668)
	org.apache.jasper.compiler.Node$CustomTag.accept(Node.java:1544)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.Node$Visitor.visitBody(Node.java:2441)
	org.apache.jasper.compiler.Node$Visitor.visit(Node.java:2447)
	org.apache.jasper.compiler.Node$Root.accept(Node.java:470)
	org.apache.jasper.compiler.Node$Nodes.visit(Node.java:2389)
	org.apache.jasper.compiler.TagFileProcessor.loadTagFiles(TagFileProcessor.java:691)
	org.apache.jasper.compiler.Compiler.generateJava(Compiler.java:232)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:373)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:350)
	org.apache.jasper.compiler.Compiler.compile(Compiler.java:334)
	org.apache.jasper.JspCompilationContext.compile(JspCompilationContext.java:595)
	org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:382)
	org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
	org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
	javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
	<omiting spring framework stack>
Note The full stack trace of the root cause is available in the server logs.

Apache Tomcat/8.5.34

As said the culprit is Generator.TagHandlerInfo's tagHandlerClass, but why ? :)

I am unable to reproduce the problem with Tomcat 8.5.24, maybe related to changes done in https://bz.apache.org/bugzilla/show_bug.cgi?id=62603 ?
Comment 1 Mark Thomas 2018-09-25 19:09:07 UTC
Do you have a test case to reproduce?
Comment 2 Jordi Llach 2018-09-26 13:27:08 UTC
By deactivating "checkInterval" in JspServlet's init config param the problem dissappears. Also notice that we set to false the "development" init param

I can consistently reproduce the problem with a huge project, I am creating a small new one to highlight the problem

BTW I've tested this with 8.5.32 and it works fine. And it starts failing with 8.5.33 onwards
Comment 3 Jordi Llach 2018-09-27 18:14:45 UTC
Created attachment 36169 [details]
patch for the reported bug


I've found the problem, JspServletWrapper's loadTagFile should check whether it has to reload by only checking the reload attribute, and not by using getReloadInternal() method, otherwise during application startup JspRuntimeContext's checkCompile can prevent some tag files to be loaded, because it changes the value of the flag compileCheckInProgress, as we saw in the stacktrace that comes from the TagFileProcessor.

I attach a patch file where I also have added some extra checks or code reordering to avoid possible paranoic scenarios, maybe I am too paranoic right now :)
Comment 4 Mark Thomas 2018-10-01 19:24:46 UTC
I can't tell which part of the patch is addressing this issue and which parts are addressing other issues - or what those issues are. Given I've already managed to introduce a regression here I'm hesitant to make more changes than I need to - especially without an explanation of why those changes are required.
Comment 5 Jordi Llach 2018-10-01 21:24:58 UTC
Thanks for the feedback, I can perfectly understand the rationale of your comment
 
As said the problem is in JspServletWrapper's loadTagFile method, it should check whether it has to reload or not by only checking the reload attribute, and not by using getReloadInternal() method. Otherwise during application startup JspRuntimeContext's checkCompile method can prevent some tag files to be loaded, because it changes the value of the flag compileCheckInProgress, as we saw in the stacktrace that comes from the TagFileProcessor.

I also noticed that JspServletWrapper's getDependants and loadTagFile methods change reload attribute without proper synchronization, as JspServletWrapper's getServlet and setServletClassLastModifiedTime do, so I "fixed" it, but that was not the problem, maybe unnecessary ?

Maybe I am wrong but I also realized that JspServletWrapper's getServlet method should execute always in case JspServletWrapper's attribute theServlet is null. With the previous code JspRuntimeContext's checkCompile method could prevent a first request to a jsp to initialize its JspServletWrapper's attribute theServlet because it set compileCheckInProgress to true and thus getReloadInternal method returns false

About TagFileProcessor change, I just fully initialized JspServletWrapper's JspCompilationContext prior puting the former into the Map managed by JspRuntimeContext. The rationale behind this change is that given that JspRuntimeContext's checkCompile will iterate through this Map of jsp/tags I just wanted to ensure that their content is fully initialized.
Comment 6 Mark Thomas 2018-10-02 20:30:34 UTC
*** Bug 62792 has been marked as a duplicate of this bug. ***
Comment 7 Mark Thomas 2018-10-02 20:43:28 UTC
Created attachment 36186 [details]
Alternative patch

Thanks for the additional explanation. I agree with all of it. I had similar concerns when I was reviewing your original report. An additional concern was that the code seemed to be getting more fragile. In particular, firstTime and theServlet == null seemed to be doing the same thing (and ditto for tagHandlerClass).

In an effort to address this, I have worked up an alternative patch that removes firstTime. I have attached it to this report. Feedback on that patch would be appreciated - particularly if you are able to test it in your environment which is likely to be more complex than the simple tests I have been doing with the example app.
Comment 8 Jordi Llach 2018-10-02 21:21:35 UTC
Cool, I'll review it and test it tomorrow
Comment 9 Jordi Llach 2018-10-03 10:27:02 UTC
The way you've solved the issue in JspServletWrapper's loadTagFile method by checking whether tagHandlerClass is null (in the second synchronized block) is better than mine. Also, removing firstTime from JspServletWrapper's getReloadInternal method makes a lot of sense

I agree that checking "firstTime" and "theServlet / tagHandlerClass" attributes overlaps someway, but firstTime also allows us to to avoid checking whether we have to compile the same resource multiple times in a scenario with multiple concurrent requests, by avoiding the the call to Compiler's isOutDated method on each concurrent request (this could be relevant with complex nested jsp/tag files)

Because of that IMHO I would suggest the following changes in JspServletWrapper class

- service method : I would check firstTime flag instead of theServlet
- loadTagFile method : in the first synchronized block I would use firstTime flag instead of checking whether tagHandlerClass is null

Maybe firstTime should be renamed to compile ?

The most important thing ... I've tested the patch and it solves the issue
Comment 10 Mark Thomas 2018-10-03 14:40:05 UTC
Thanks for the additional review. The point regarding isOutDated() is a valid one. I have adjusted the patch to take account of that feedback.

The fix has been applied to:
- 9.0.x for 9.0.13 onwards
- 8.5.x for 8.5.35 onwards
- 7.0.x for 7.0.92 onwards

Thanks again for your work on this issue.
Comment 11 Jordi Llach 2018-10-19 09:41:05 UTC
Any ETA for Tomcat 8.5.35 ?

Thanks

J