WebActivatorEx重复执行?不!那是作为使用者的我们傻逼!!

作者：V君 发布于：2018-6-15 22:42 Friday 分类：挖坑经验

TL;DR:

如果在发布新版本后出现疑似WebActivatorEx启动入口被执行多次的情况

首先检查bin里面是否有上个版本残留的DLL，干掉它们就解决了，然后把锅甩给运维。

 

那么，开始我的故事。


～前奏～


由于首次在正式项目引入git源代码管理体系，仓库结构设计的相当散乱。

这不赶上重组git仓库，重新建立了解决方案，命名空间和项目名称也重新规划了。


～嘣咧挫～


好不容易发布一个新版本到测试环境，运行起来出现致命错误的黄页。

连最开始的初始化都没完成，错误处理也措手不及，好久不见的黄页就这样呈现出来。


～扯一扯～


由于不喜欢Log4Net这种只能用配置文件的充满Java味道的东西。

现在项目中的日志组件是由我自己实现的，有以下特性：

  • 由写入时间决定文件名
  • 6个级别，外加可选启用的虚拟级别“ALL”将其他级别内容凑一起输出
  • 按指定大小分文件
  • 多次启停可续写
  • 自动删除指定天数的旧文件

写入方式是基于线程安全的FileStream共享只读打开，方便边写边看。

内容格式是三行一空行的条目：

  • 第一行写时间、级别、线程信息（如果有写程序集，也能快速发现这次的问题。之后补上吧）
  • 第二行写摘要，由开使用者定义的简短摘要
  • 第三行写详情的JSON，有日志位置堆栈，可以加入任意对象作为附加信息

在日志组件初始化之后，我通常会打一句“Logger Init”在日志中体现应用程序启动。

我们有为此专门做了个小工具来分析日志，用上了Chris Nielsen的JSON可视化界面实现。


～诊断～


打住，话题收回来，黄页的错误信息是“文件被占用”，堆栈显示正在打“Logger Init”时…

一开始的时候很有自信，以为自己写的实现没问题，可能被文件共享出来占用了。

用Procexp查文件句柄,一个都没查出… 

但作为应用程序启动的体现“Logger Init”却被打进日志文件里…

老大的意思是想让我先把多节点负载均衡砍掉，以单节点跑起来，降低复杂度再诊断。

当时没辙只好听话照办喽，然并卯。

还是掏出诊断大杀器ProcMon看看“是谁动了我的奶酪”，看到结果时开始觉得自信不足了：

——真的是ASP.NET程序池进程访问的文件，而且是同一条原生线程访问了两次。

——第一次成功打开，第二次打开失败，最后还把文件关闭了——由CLR，程序都崩溃了嘛！

难道是自己的实现有问题，多线程竞态现象？

.NET的托管线程可能会复用原生线程，出现TID一样的情况也不能排除多线程。

在初始化的地方加了锁，然而问题依旧存在。其实并不是我的代码写的不严谨，这是后话。


咋办？


让文件打开的共享模式可读可写吧，想到了这样高风险的激进尝试。

然而——还是失败了，但仔细观察发现ProcMon监视条目详情有蹊跷：

第一次打开文件的共享模式是只读，第二次才是符合激进尝试的可读可写。

两次打开文件的原生堆栈有差异，很可惜看不到托管堆栈，如果能看到程序集就能解决问题了。

远程调试吧。没办法的办法了，在日志初始化的地方打个断点看看会不会两次命中。

调试结果令人十分失望，只命中了一次，打开失败的第二次。天知道第一次在哪儿打开？

这时猫同事建议我把“Logger Init”改一下，看看有没有打出来。这才恍然大悟。

我拒绝了建议，且断言上个版本残留程序集，去服务器bin看看，断言成立！

抓住运维的肩膀使劲晃，“你让我浪费了两天的时间排查”　乂目


～结语～


甩完锅之后还是要总结一下教训的，发布版本应该将之前的文件干掉，再把新的包部署上去。

标签: 软件开发 C# ASP.NET 软件故障诊断

评论(0) 引用(0) 浏览(1310)

Powered by emlog 去你妹的备案 sitemap