蹊跷的ThreadDeath，令人郁闷的glassfish

     最近公司的项目即将完成，正要进行最后的回归测试，正式release的时间线也快到了，比较紧张。结果就在这种关键时刻，在周五下午(恩，快下班的时候，我最恨这个时间出错了)，发生一个bug：这个bug发生的几率极低，而一旦发生这个系统的traffic 都会因为这个bug报错退出。由于发生在关键时刻，于是被极度重视，当场召集人员开会，决定一定要第一时间查找出原因并尽快解决。

    能够让系统的每个traffic请求都失败的bug，这个严重程度不言而喻。好吧，谁让我们是程序员呢，看看bug是怎么回事吧？

    其实问题的表现很简单：在请求处理过程中，抛出了一个ThreadDeath 的error：


Caused by: java.lang.ThreadDeath
        at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1413)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
        at se.ericsson.nrg.ws.realms.nrgcommonentities.service._ApplicationServiceSubscriptionRemote_DynamicStub.searchBySpIdAndAppIdAndScPk

(se/ericsson/nrg/ws/realms/nrgcommonentities/service/_ApplicationSe
rviceSubscriptionRemote_DynamicStub.java)
        at se.ericsson.nrg.ws.realms.nrgcommonentities.service.ApplicationServiceSubscriptionDAORemoteImpl.searchBySpIdAndAppIdAndScPk(ApplicationServiceSubscriptionDAORemoteImpl.java:104)
        ... 74 more

    坦白说，每次看到ThreadDeath这个error，我都有种一头撞死的感觉, ^0^，谁取的这名字！由于之前遇到过类似的问题，因此倒是不特别紧张，先看看请求处理的过程：首先是一个webapp接收请求，然后请求被交给一个 EJB的模块处理，ThreadDeath error就是在这里抛出。从ThreadDeath的exception trace上看到，

at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1413)


    说明当前线程是试图用webapp的classloader来装载类，然后遭遇ThreadDeath，随即在日志文件中查找到这样的内容：

[#|2010-05-24T15:19:26.702+0800|INFO|sun-glassfish-comms-server2.0|org.apache.catalina.loader.WebappClassLoader|_ThreadID=47;_ThreadName=httpWorkerThread-48080WorkerThread-8080-337;|PWC1635: Illegal access: this web application instance has been stopped already (the eventual following stack trace is caused by an error thrown for debugging purposes as well as to attempt to
terminate the thread which caused the illegal access, and has no functional impact)|#]


    "this web application instance has been stopped already"，进一步证实了我们的猜测，这个是最常见的ThreadDeath 的发生场景了，简单描述一下：

    1. 工作线程执行webapp的请求，webapp的classloader被保存在thread
        类似Thread.setContextClassLoader(WebappClassLoader)这样的方式
    2. webapp被restart/redeploy ，但是由于某些原因上面的工作线程中保留的webapp的classloader并没有被清理

    3. 这个工作线程继续处理请求，由于他使用的classloader是restart/redeploy前的webapp的，现在这个webapp已经不复存在，因此出现ThreadDeath 错误

    有关ThreadDeath的类似错误，glassfish上有个wiki特地描述了这个问题。

http://wiki.glassfish.java.net/Wiki.jsp?page=FaqWebAppStoppedIllegalAccessError

    正在我们以为找到问题准备继续查找看是哪里的Thread.setContextClassLoader()方法出现问题时，被另外一个发现击倒！我们发现上述的ThreadDeath 在重新启动之后居然可以立即重现！很晕，按照上面的推断逻辑，如果我们关闭glassfish，即关闭jvm，退出进程，然后重启启动，ThreadDeath 就应该消失才是，因为出问题的Thread随jvm一起退出了。新jvm中启动的Thread不再有残余的classloader来导致 ThreadDeath。

    这个证据直接推翻前面的推断，看来问题不是这个简单了。

    随后进行了大量的查找，推断和尝试，过程不叙述了。最后发现在日志中有一个异常，坦白说我们的日志有点多，有点乱，不是很好查找问题：

javax.servlet.ServletException: java.lang.ClassCastException: java.lang.Long cannot be cast to java.lang.Integer
at se.ericsson.nrg.ws.service.http.SIGAuthenticationFilter.init(SIGAuthenticationFilter.java:162)
at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:273)
at org.apache.catalina.core.ApplicationFilterConfig.setFilterDef(ApplicationFilterConfig.java:385)
at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:119)
at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4521)
at org.apache.catalina.core.StandardContext.start(StandardContext.java:5369)
at com.sun.enterprise.web.WebModule.start(WebModule.java:345)
at com.sun.enterprise.web.LifecycleStarter.doRun(LifecycleStarter.java:58)
at com.sun.appserv.management.util.misc.RunnableBase.runSync(RunnableBase.java:304)
at com.sun.appserv.management.util.misc.RunnableBase.run(RunnableBase.java:341)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)


    webapp中定义有一个filter，现在这个filter在init()方法中出现异常，而我们编码的时候会包装这个异常然后以 ServletException的方式抛给容器。

    init()方法中出现的异常是一个配置项的类型不正确，做强制类型转换时失败导致。由于出现这个配置问题的脚本偶尔才运行，因此过去这个错误发生的几率极低。随即修复了这个配置项，重启glassfish后验证成功，ThreadDeath 错误消失，系统工作正常。

    OK，问题找到并得到确认。

    可是这里依然有一个巨大的疑问：为什么一个filter抛出的ServletException，会导致glassfish出现"判断失误"从而认定 webapp是"stopped"状态以致最后以ThreadDeath的形式来体现错误？

    这个案例比较迷惑人的地方是，filter抛出的ServletException后，这个webapp是可以正常接收请求也可以正常将请求转交后面的业务处理模块，控制台上也看不到这个webapp的任何状态异常。

    特地找了一下j2ee5规范，没有发现有对filter的详细要求，随即找到了j2ee 5的 API，在API文档中发现以下内容：

void init(FilterConfig filterConfig)
          throws ServletException
Called by the web container to indicate to a filter that it is being placed into service. The servlet container calls the init method exactly once after instantiating the filter. The init method

must complete successfully before the filter is asked to do any filtering work.

The web container cannot place the filter into service if the init method either
1.Throws a ServletException
2.Does not return within a time period defined by the web container


    这里可以看到，当发生ServletException 异常时，“The web container cannot place the filter into service”，既这个filter应该不能生效才是。而且也没有任何其他说明说ServletException会导致其他问题比如webapp不能启动，不能工作之类的。

    当时实际上，我们在检查ThreadDeath的调用信息时，发现有下面的调用

at se.ericsson.nrg.ws.service.http.SIGAuthenticationFilter.doFilter(SIGAuthenticationFilter.java:89)


    说明这个出现init()错误的filter还是被glassfish正常调用去执行doFilter()方法，这里和j2ee API的要求是不符合的。有点奇怪的是，glassfish一向是以严格遵循j2ee规范而著称，居然在这里一反常态。

    而更令人 郁闷的是，glassfish在处理这个有filter初始化出现ServletException异常的webapp时的前后表现：首先这个 webapp的启动没有问题，状态正常。filter也被认为可以正常工作并加入了filter链。webapp中的功能正常，可以正常的接收请求并转发给内容业务处理模块。从这些迹象看这个webapp基本没有问题。但是后面glassfish却莫名其妙的认定，“this web application instance has been stopped already”，从而以ThreadDeath这种非常规的error来报错。

    这个做法令人比较难于接收，如果filter初始化出现ServletException异常会导致webapp的状体异常，那么glassfish应该在第一时间直接给出这个判断，比如直接让webapp就启动失败之类的，这样不至于将这个错误推迟到一个非常遥远的地方才被暴露，而且filter ServletException异常 -》 ThreadDeath 的这种因果关系未免有点牵强，查错时根本没有可能直接联系上，导致查错的难度大增。

    不得不再次批评一下glassfish，从产品质量上看，glassfish和weblogic的差距还真是不小。