“遛”出来的附加值

“遛”出来的附加值

前言

       午饭后，很多同事都会叫上自己的“遛友”，三五成群的在园区里溜几圈。遛弯能够消消食，呼吸一下户外空气，聊聊天、探讨一下人生。

当遛弯成为一种习惯后，即使是三伏天，中午一个人，也会去C座水池旁站一站，走一走。一次遛弯，不只是身在遛弯，很多时候还是思在遛弯。有时候一直冥思苦想的问题，遛个弯就会灵光一现，柳暗花明。但标题所说的附加值，是另一种带有点责任的遛弯。

缘由

现在生产上所跑的各个业务系统，几乎没有任何监控可言，几乎等同于裸奔。研发人员若是想了解系统的运行状况必须去ECC登录服务器看日志（多么原始的方法）。平常遛弯的时候，路过C座，花个5分钟去ECC查看一下服务器日志，掌握一下自己所负责的业务系统的运行情况。下面这三个异常日志片段就是在7月下旬遛弯时，在ECC登录服务器查看日志所发现的。基于发现的问题“及时”进行了解决，避免极端情况下造成生产事故，这就是“遛“出来的附加值。

第一片段： 正在上传…重新上传取消正在上传…重新上传取消

第二片段： 正在上传…重新上传取消正在上传…重新上传取消

第三片段： 正在上传…重新上传取消正在上传…重新上传取消

当16日发现第一个片段时，第一感觉就是cookie已失效，导致校验失败，很普通的一种情况。根据对源码的记忆，能够解释的通。

当22日发现第二个片段时，本能的感觉就是getWriter被多次调用时会有此异常，或者同一个Response，既调用了outputStream又调用了getWriter时也会有此异常，经常见。理论上对业务没任何影响。

当24日（当日结算后，17点有版本要上仿真）仿真升级完后，看看生产系统日志，发现了第三个异常。502网关超时，同时又发现了第二个片段同样的异常，这时有点解释不了了。网关超时，是由下游服务有问题（应用网关所反向代理的服务挂掉），理论上并不会出现getWriter的异常。咨询系统运行中心人员，也没有相关人员反应系统有问题。但是没人反应，并不代表没问题。仿真升级完后，带着拷贝的日志，待周六加班时进行分析。

Ship Code

三个不同时间段发生的异常，看似毫无关联，但最终分析下来，却是相同的一段代码造成的。

当第一个异常片段发生时，没有认真对待、抓住机会，让这个问题逃逸了。当第二个异常片段发生时，基于本能的感觉去下结论，与发现问题的契机又完美的错过了。当第三个异常发生时，联想到第二次的异常，这才引起足够的重视。

有时候发现问题也是需要机缘巧合的，很多问题可能会由于自身“自带过滤“机制给屏蔽掉了。

       周六进行了源码及日志分析，有问题的源码如下：

1 正在上传…重新上传取消正在上传…重新上传取消		2 正在上传…重新上传取消正在上传…重新上传取消
3 正在上传…重新上传取消正在上传…重新上传取消

代码片段1：服务转发的主方法，首先获取路由转发的服务配置实体，然后进行各种校验，最后转发调用。

代码片段2：校验登录Cookie是否合法，校验心跳Cookie是否过期。各自方法内部校验时，若是出错，抛出异常。在外部进行异常捕获，把异常封装进行统一的处理，url为登录页，然后调用代码片段3。

代码片段3：把信息写入响应对象中，并关闭。

3个代码片段整体上还是比较容易理解的，表面上看没什么问题。并且在生产环境上也已经运行8个月左右，也没出过什么事故。俗语说，任何事情就害怕“认真”二字，下面就基于篇头中的三个异常日志片段来细细品味这三段代码到底问题出在哪。研发人员那颗“无BUG” 的心是否能够经受的住这个研磨代码的过程。

啃骨

1. 危险的“beat the buzz”

很多系统都会设有登录的时效性，过了一定的时间，若是不操作界面，则再次点击系统的任何界面均会跳转到登录界面。上面的三个代码片段，就包含此功能。

正在上传…重新上传取消正在上传…重新上传取消

这个方法内部捕获了异常，即使方法中执行了跳转到登录页，但是阻止不了主方法继续往下进行，从而造成危险的“beat the buzz”。

比如：登录系统后，点开一个删除界面，待会话超时，点击删除按钮，会发现浏览器跳转到了登录页，同时这次的删除操作竟然被成功执行了。这就系统安全规范中的一个典型案例：危险的“压哨球”。

1. 得“底层规范“规范者，得质量

基于现在各种框架漫天飞，很少有“机会”再去了解底层最基本的Servlet规范。这就很容易导致，开发时真正涉及底层规范时“一脸MB”，编写代码跟着感觉走，只要看到结果正确，管它二舅姓啥。

异常中的“getWriter method has been called ”，若是了解底层规范，就可以明确断定之前Response调用过getWriter方法，而现在要调用getOutputStream方法。因为Response中可以写入字节流模式与字符流模式，但是只能同时存在一种模式，二种模式不能混合，这就是Servelt规范中明确写的：

正在上传…重新上传取消正在上传…重新上传取消

学而不思则罔，提个小问答题：为何Servlet要制定这个规范？可以思考一下，有想不明白的，可以一起探讨下。

既然了解了底层规范，那么就啃啃代码看看哪个地方调用了response.getOutputStream()方法（response.getWreiter()方法已经在方法片段3中被调用）。

要看哪个地方调用此方法，最简单的方式就是找到这个方法，Debug一把。这个很容易。难的是有多少个场景会调用此方法，并不是你能通过Debug方法整理出来的。这需要了解Tomcat请求响应的处理逻辑。通过阅读Tomcat源码，整体的请求流程如下图：

正在上传…重新上传取消正在上传…重新上传取消

请求响应流程图

       从上图可以看到，有两种模式会调用。一种正常请求流程，一种异常请求流程（不区分异常类型）。

1. 正常流程：Tomcat内部统一调用getOutputStream
2. 异常流程：Tomcat内部统一调用getWriter

再提个小问题：为何异常流程调用统一调用getWriter，正常流程调用getOutputStream?

所以在正常流程中，想多次输出结果，可以多次调用getOutputStream。在异常流程中，想多次输出异常明细，可以多次调用getWriter。

1. 用完请归还

打开资源，使用后关闭，这是良好的编程习惯。若是没有这个处理，好的框架也会进行兜底处理的。上面的请求响应流程图，无论异常还是正常流程，Tomcat均会调用close方法。所以代码片段3中，应该手动关闭。

解决方案：

代码中存在的问题已经很明了了，那么解决方案也呼之欲出了。为了不影响现有主逻辑的结构，只需要在代码片段2中：

正在上传…重新上传取消正在上传…重新上传取消

修改为：

正在上传…重新上传取消正在上传…重新上传取消

然后采取全局异常捕获处理即可：

正在上传…重新上传取消正在上传…重新上传取消

反思

       为何这个问题在开发、系统测试、各业务系统开发集成、各业务系统系统测试等环节均逃逸出来，这是值得反思的。

1. 研发人员对底层规范、底层原理的理解不清晰。
2. 测试阶段以目标为导向，只关注结果，而忽略了旁枝末节。
3. 第一次、第二次发现此问题时，没有引起足够的重视，凭借经验来判断，导致误断。若不是第三次异常，可能这个“定时炸弹“被发现还要延期。
4. 逃逸这么久，也是由于此问题对业务无影响，只是存在安全问题。所以安全问题在研发及测试阶段需要重视起来。

最后

程序可以在生产上没有任何监控的裸奔，但研发人员对所负责的系统不能有一颗“放任其自由“的心，要时不时的去关注一下，用仅有的日志去给系统诊断一下。在遛弯时，花5分钟去ECC遛一圈，让遛弯也产生一些别样的附加值。