问题现象:
IIS部署的asp.net core服务,前端进行一些操作后,经常需要重新登陆系统。
初步分析:
根据日志,可以看到服务重新进行了初始化,服务重启应该与IIS应用程序池回收有关,查看IIS相关日志,在windows的事件查看器=>Windows日志=>系统,来源为WAS的日志(参考博客)。
根据IIS日志与服务日志对比发现,每次服务重启对应一次WAS警告信息,详细信息为:“为应用程序池“xxx”提供服务的进程在与 Windows Process Activation Service 通信时出现严重错误。该进程 ID 为“xxx”。数据字段包含错误号。”。说明应用程序池异常崩溃后重启了。
抓取dump分析
为了找到程序池崩溃的原因,抓取dump进行分析,如何抓取dump见文档,使用DebugDiag工具进行抓取,抓取后使用DebugDiag进行初步分析,如下图:
可以看出是线程池中的线程抛出了异常,应为异步代码导致,但没有指出具体引发异常的服务代码。尝试使用WinDbg进行进一步分析,然而并不能看懂卦象,进行了一波操作后并没有找到问题原因。
反编译调试
由于dump的分析报告没有给出根本原因,也不熟悉如何深入分析dump,因此换个思路,通过测试找到了问题必现的某个请求操作后,尝试进行反编译调试,看能不能找到引发异常的根本原因。为什么不直接用VS调试呢,因为出问题的项目请求代码没看出来啥问题,本地也没有复现。公司框架代码看不到源码,框架近期进行了大的修改,怀疑框架代码导致的问题。因此模拟环境进行反编译调试,应该更容易找到问题原因。
首先创建虚拟机,部署服务,搭建测试环境,与生产环境保持一致。然后使用dnSpy工具反编译调试,将项目文件拖到dnSpy中,调试-附加到进程(w3wp),打断点进行跟踪。
然而进行了多次调试操作后,因为异常是在某个线程中触发的,并没有跟踪到异常产生的位置。结合dump分析结果给出的信息,尝试在一些异步的操作位置打断点,也没有跟踪到导致程序池崩溃的异常。
排除法
进行了多次反编译调试后,没发现原因,因此重新梳理思路,采用排除法继续测试。将可疑的代码片段注释掉,然后编译放到测试环境中进行调试。经过几次测试,锁定了导致崩溃的代码片段。跟踪这段代码,发现了一个空指针异常。其实这个异常在反编译调试的时候就发现了,抛出后clr捕获了异常,请求继续往下走,请求走完后又在clr代码中抛出了异常,然后程序池挂掉。现在锁定了就是这段代码导致,需要进一步查看代码分析为什么会导致应用程序池崩溃。
通过反编译调试获取导致异常的条件后,在本地进行模拟复现。发现异常首次出现后,程序继续运行,当请求结束后,又回到了异常出现的位置,然后崩溃。仔细检查这段代码,发现竟然使用了async void...
异常模拟
熟悉C#异步编程的都知道,应避免使用async void,返回void是为了支持异步事件处理程序,参见官方文档。当async Task或async Task
异常模拟如下,项目中异常引发的位置非常隐蔽,因此很难发现:
try
{
TestAsyncVoid();
}
catch(Exception ex)
{
Console.WriteLine(ex);
}
async void TestAsyncVoid()
{
throw new Exception("------------test-------------");
}
运行截图如下:
总结与反思
之所以导致应用程序池崩溃,需要具备如下条件:
- 使用了async void;
- 在async void内部出现了异常且没有处理;
应避免使用async void,只有在异步事件处理时才返回void,否则应该返回Task或Task
此次应用程序池崩溃问题处理耗费了一天多的时间,复盘下问题分析的过程,如果一开始就把注意力放在引起程序崩溃的请求代码上,应该会更快的发现问题。但是之前同事通过修改IIS应用程序池配置,阴差阳错的修复了一个导致崩溃的请求。而且公司框架代码进行过大的调整,导致分析方向出现了错误,关注点放在了公司框架代码上。反编译调试的时候,其实已经发现了项目代码有异常,但认为这种异常不会导致崩溃,且请求继续执行了,因此依然没意识到方向错了。最后通过排除法发现,问题出在项目代码上,才找到根本原因。因此,分析问题的过程中,当发现方向可能不对时,应停下来重新整理信息,梳理思路,从最直接的起因入手进行分析,可以更快的解决问题。
转载请注明出处,欢迎交流。