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

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

TL;DR:

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

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

 

那么,开始我的故事。


~前奏~


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

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



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

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


~扯一扯~


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

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

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

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

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

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

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

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


~诊断~


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

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

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

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

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

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

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

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

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

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

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

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


咋办?


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

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

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

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

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

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

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

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

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


~结语~


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

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

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

Powered by emlog 去你妹的备案 sitemap