一個Slash引發(fā)的ClassNotFound血案

背景介紹

公司開發(fā)了一款Web應(yīng)用，開發(fā)架構(gòu)基于Spring Boot，通過jar包的方式發(fā)布到服務(wù)器并通過命令行運行在內(nèi)置的Tomcat上。

上線將近一年，一切都是那么的風平浪靜，然而一切的平靜被上周的一次現(xiàn)場算法回訪打破。

我們的數(shù)據(jù)分析人員本意只是想查看一下歷史數(shù)據(jù)來確認算法的表現(xiàn)符合預(yù)期，結(jié)果發(fā)現(xiàn)歷史數(shù)據(jù)查詢頁面怎么點都沒有反應(yīng)，而其他頁面都是正常的，服務(wù)重啟后一切恢復正常。

?

問題重現(xiàn)

雖然問題通過服務(wù)重啟后成功解決，但是出錯的原因沒有定位到也就意味著再次出錯的可能性依然存在。

?

分析問題最直觀的方式就是從錯誤出發(fā)，通過錯誤信息來反向推導錯誤發(fā)生的場景。在這個案例中我們查看了瀏覽器控制臺和后臺錯誤日志，最終獲取了準確的錯誤信息：

2019-08-23?14:40:47,835?[http-nio-9090-exec-8]?ERROR?o.a.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[dispatcherServlet]?-?Servlet.service()?for?servlet?[dispatcherServlet]?in?context?with?path?[]?threw?exception?[java.lang.ClassNotFoundException:?org.apache.jsp.WEB_002dINF.views.report.report_005fmain_jsp]?with?root?cause
java.lang.ClassNotFoundException:?org.apache.jsp.WEB_002dINF.views.report.report_005fmain_jsp
????????????at?java.net.URLClassLoader.findClass(URLClassLoader.java:381)
????????????at?org.apache.jasper.servlet.JasperLoader.loadClass(JasperLoader.java:129)
????????????at?org.apache.jasper.servlet.JasperLoader.loadClass(JasperLoader.java:60)
????????????at?org.apache.catalina.core.DefaultInstanceManager.newInstance(DefaultInstanceManager.java:159)
????????????at?org.apache.jasper.servlet.JspServletWrapper.getServlet(JspServletWrapper.java:171)
????????????at?org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:380)
????????????at?org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:386)
????????????at?org.apache.jasper.servlet.JspServlet.service(JspServlet.java:330)
????????????at?javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
????????????at?org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
????????????at?org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
????????????at?org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
????????????at?org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
????????????at?org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
????????????at?org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:728)
????????????at?org.apache.catalina.core.ApplicationDispatcher.proce***equest(ApplicationDispatcher.java:470)
????????????at?org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:

?

這是一個ClassNotFoundException，通過錯誤信息我們可以在搜索引擎上找到一堆解答，甚至在Spring Boot的Github上都有類似的情況。

https://github.com/spring-projects/spring-boot/issues/5009

結(jié)果總結(jié)下來就是：

Spring Boot內(nèi)置的Tomcat會在系統(tǒng)根目錄的/tmp下創(chuàng)建Tomcat開頭的臨時目錄，tmp目錄的定時清理會導致部分文件的class文件找不到，

解決辦法是指定一個work目錄不要使用默認的tmp目錄。

?

聽起來很有道理，官方都這么說了那照著做就行了唄。

然而作為一個好奇心爆棚的程序員，這樣的解釋顯得蒼白而無力，但是這個解釋倒是給我們的重現(xiàn)提供了很好的便利，畢竟只有充分重現(xiàn)了這個問題才能更好的去探究深層次的原因。

?

于是在官方解釋的指導下，我們進行了多次重現(xiàn)的嘗試，最終將問題范圍縮小如下：

在Tomcat啟動后將tmp下的ROOT目錄刪除，訪問的第一個頁面會出現(xiàn)無法訪問的情況，后臺出現(xiàn)ClassNotFoundException，之后再訪問其他頁面都是正常。

?

這里補充一下背景知識：tmp目錄在Centos6以及之前是通過TmpWatch的定時任務(wù)來定時清理，而Centos7之后直接修改為了systemd-tmpfiles-setup.service，配置文件在/usr/lib/tmpfiles.d/tmp.conf。

問題分析

在進行問題分析的時候，我們一般會使用三種方式

2? 經(jīng)驗法

結(jié)合自身的經(jīng)驗來猜測問題發(fā)生的可能原因，然后通過驗證來定位問題具體原因

2? 推導法

從問題的發(fā)生點開始倒推，沿著問題發(fā)生的路徑逐步接近問題的根源

2? 分析法

分析整個流程中的每一個節(jié)點，找到和問題可能相關(guān)的節(jié)點逐個驗證從而找到導致問題的節(jié)點

?

經(jīng)驗法往往是遇到問題時第一個使用的方法，因為面對問題時沖在前面的往往是我們的直覺。

在這個問題中我做了以下猜測，并一一驗證

1， Class文件損壞

做出這個假設(shè)的依據(jù)是，在同一個目錄下存在兩個頁面的Class文件，一個可以訪問一個不可以訪問。

驗證方法也很簡單，首先重啟服務(wù)正常訪問頁面A獲取到正常狀態(tài)下的A.java和A.class文件；重啟服務(wù)器后刪除ROOT目錄，再訪問頁面A觸發(fā)錯誤，將目錄下的java和class文件替換成正常狀態(tài)的問題；再次訪問頁面，依然報錯。

至此我們推翻了我們關(guān)于Class文件損壞的假設(shè)。

2， Dev-tool導致ClassLoader不一致

做出這個假設(shè)的依據(jù)是我們之前遇到的一個dev-tool的問題，Spring Boot在引入了dev-tool后會進行熱加載，這時候由于jar包加載和class加載使用了不同的ClassLoader會出現(xiàn)ClassNotFoundException。

我們之前解決這個問題的方法是去掉dev-tool，同樣在這里我們也可以去掉dev-tool再走一遍重現(xiàn)步驟，發(fā)現(xiàn)問題依然存在。

至此我們排除了Dev-tool導致ClassLoader不一致的假設(shè)。

3， Class文件時間戳

在我們查看正常文件和異常文件差異的時候發(fā)現(xiàn)，正常文件的時間戳和jar包中的jsp時間戳一致，而異常文件的時間戳是當前時間，那會不會是因為時間戳不一致導致的呢。

為了驗證這個假設(shè)我們從兩方面入手a) 調(diào)整正常文件的時間戳到當前時間，結(jié)果正常文件依然正常 b) 調(diào)整異常文件的時間戳為jsp的時間，結(jié)果異常文件依然無法訪問。

于是我們也排除了Class文件時間戳的假設(shè)。

?

?

推導法是比較直觀也是可以比較快速的發(fā)現(xiàn)問題的方法，但是在我們這個案例中我們發(fā)現(xiàn)錯誤堆棧中的URLClassLoader并不是問題發(fā)生的第一現(xiàn)場，真正的第一現(xiàn)場在java自己的包中，對我們逐步跟蹤問題造成了困難。

?

鑒于此我們選擇分析法作為我們解決問題的突破口。當然還有一個重要條件支持我們采用分析法解決問題，那就是在我們這個案例中我們存在OK和NOK兩種情況，在每一個分析的節(jié)點我們都可以引入兩種情況進行對比。

?

在開始之前，由于要每一步比較差異，我們需要配置Eclipse的遠程調(diào)試。傳送門：

https://www.cnblogs.com/east7/p/10285955.html

?

首先我們梳理一下Tomcat解析JSP的流程，由于我們基于類來描述流程，所以先羅列一下涉及的類以及主要的方法：

?

JspServlet類是主入口，接收jsp請求；

JspRuntimeContext通過add和get方法來維持一個ServletWrapper的緩存；

從JspServlet往后是加載的主要類，而從Compiler往后的類是編譯用到的類。?

在大致了解了內(nèi)部類結(jié)構(gòu)后我們可以來看看Jsp加載的流程了，

?

從圖中可以看出我們的報錯點在獲取Servlet的class這一步，那么我們從頁面訪問的步驟一步步比較OK和NOK表現(xiàn)的差異。

1， 獲取ServletWrapper

這一步的作用是為每一個Jsp頁面構(gòu)建一個代理并緩存在JspRuntimeContext中，這樣每次訪問頁面直接獲取代理即可。從調(diào)試的結(jié)果看，構(gòu)建wrapper的每個參數(shù)都是一樣，而構(gòu)建的wrapper結(jié)果也是一致的。

2， 編譯Java文件

我們注意到在Complier.class的generateJava這個方法中有一步是：

ctxt.checkOutputDir();

我們的重現(xiàn)恰恰是刪除了ROOT目錄，繼續(xù)進去看代碼

public?void?checkOutputDir()?{
????????if?(outputDir?!=?null)?{
????????????if?(!(new?File(outputDir)).exists())?{
????????????????makeOutputDir();
????????????}
????????}?else?{
????????????createOutputDir();
????????}
}

?

由于一開始的outputDir為空會進入createOutputDir方法，

??try?{
????????????File?base?=?options.getScratchDir();
????????????baseUrl?=?base.toURI().toURL();
????????????outputDir?=?base.getAbsolutePath()?+?File.separator?+?path?+
????????????????????File.separator;
????????????if?(!makeOutputDir())?{
????????????????throw?new?IllegalStateException(Localizer.getMessage("jsp.error.outputfolder"));
????????????}
????????}?catch?(MalformedURLException?e)?{
????????????throw?new?IllegalStateException(Localizer.getMessage("jsp.error.outputfolder"),?e);
????????}

這里對baseUrl進行賦值，聯(lián)想到之前看到一個關(guān)于UrlClassPath加載資源的解讀，ucp類會根據(jù)baseUrl來加載不同的loader進行資源加載。

通過debug我們發(fā)現(xiàn)這個地方的baseUrl在OK和NOK兩種情況下確實存在差異。

NOK：

baseURL = file:/tmp/tomcat.2612162063177545213.9090/work/Tomcat/localhost/ROOT

OK：

baseURL = file:/tmp/tomcat.2612162063177545213.9090/work/Tomcat/localhost/ROOT/

對照ucp的代碼

??private?Loader?getLoader(final?URL?url)?throws?IOException?{
????????try?{
????????????return?java.security.AccessController.doPrivileged(
????????????????new?java.security.PrivilegedExceptionAction<Loader>()?{
????????????????public?Loader?run()?throws?IOException?{
????????????????????String?file?=?url.getFile();
????????????????????if?(file?!=?null?&&?file.endsWith("/"))?{
????????????????????????if?("file".equals(url.getProtocol()))?{
????????????????????????????return?new?FileLoader(url);
????????????????????????}?else?{
????????????????????????????return?new?Loader(url);
????????????????????????}
????????????????????}?else?{
????????????????????????return?new?JarLoader(url,?jarHandler,?lmap,?acc);
????????????????????}
????????????????}
????????????},?acc);
????????}?catch?(java.security.PrivilegedActionException?pae)?{
????????????throw?(IOException)pae.getException();
????????}
}

?

我們發(fā)現(xiàn)當出現(xiàn)”/”的時候我們是通過fileLoader來加載資源，而沒有”/”的情況我們默認到jarLoader，用jarLoader去加載一個文件路徑當然會返回ClassNotFound了。

?

至此我們終于將這個問題的來龍去脈理清楚了，那這一個"/"的差異是怎么來的呢，回到那段代碼片段：

??baseUrl?=?base.toURI().toURL();
??outputDir?=?base.getAbsolutePath()?+?File.separator?+?path?+
????????????????????File.separator;
?if?(!makeOutputDir())?{

OK和NOK的情況base是一樣的，唯一的區(qū)別就是OK的情況文件目錄都是存在的，而NOK的時候文件夾是沒有的，是不是這種差異導致了一個”/”的差異呢，還是看代碼吧：

base.toURI():

public?URI?toURI()?{
????????try?{
????????????File?f?=?getAbsoluteFile();
????????????String?sp?=?slashify(f.getPath(),?f.isDirectory());
????????????if?(sp.startsWith("http://"))
????????????????sp?=?"http://"?+?sp;
????????????return?new?URI("file",?null,?sp,?null);
????????}?catch?(URISyntaxException?x)?{
????????????throw?new?Error(x);?????????//?Can't?happen
????????}
????}

Slashify():

private?static?String?slashify(String?path,?boolean?isDirectory)?{
????????String?p?=?path;
????????if?(File.separatorChar?!=?'/')
????????????p?=?p.replace(File.separatorChar,?'/');
????????if?(!p.startsWith("/"))
????????????p?=?"/"?+?p;
????????if?(!p.endsWith("/")?&&?isDirectory)
????????????p?=?p?+?"/";
????????return?p;
}

?

從上面的代碼可以看出只有滿足isDirectory的判斷才會給URI加上"/"，在我們NOK的情況下由于文件夾不存在isDirectory返回false不會加上結(jié)尾的"/”，導致了baseURI的差異，并最終導致了ClassNotFoundException的生產(chǎn)血案。

?

總結(jié)

在這個案例中我們主要使用了經(jīng)驗法和分析法來定位問題，查找本源。

在經(jīng)驗分析的過程中我們遇到了阻礙，轉(zhuǎn)而通過分析法分解了Tomcat對于Jsp請求的處理流程。

在分析Jsp編譯過程時發(fā)現(xiàn)會對baseURI進行賦值，結(jié)合我們已有的對URLClassLoader的加載過程的理解，于是我們對于baseURI的處理進行了著重分析。

最終發(fā)現(xiàn)由于baseURI賦值時系統(tǒng)環(huán)境的差異導致了生成的baseURI產(chǎn)生了一個”/”的差異，而這一個差異又導致資源加載的加載器選擇差異，最終導致不合適的加載器加載不到資源的錯誤。

?

在問題的解決上我們還是沿用官方的說法，指定一個tmp url用來存放tomcat的臨時文件，避免系統(tǒng)服務(wù)定時刪除。

-Djava.io.tmpdir=/xxx_web_root

?

參考材料：

https://github.com/spring-projects/spring-boot/issues/5009

http://www.docjar.com/html/api/sun/misc/URLClassPath.java.html

https://www.jianshu.com/p/b8e331840961

http://www.jinbuguo.com/systemd/tmpfiles.d.html#

?