记一次监控问题解决历程

每次必写的前言

这周的周一我们老大请了一天假，本来这该是一个多么美好的周一啊，打打盹，看看邮件什么的，时间很快就过去了不是吗。可是老天爷注定不让我度过一个愉快的周一。它扔给我一个毫无头绪的难题。困扰了我一天一夜(真的做梦也梦到这个问题了)后，问题被定位了(也随手被解决了)。我想我必须要记录下来，一方面是对解决问题过程的一个回顾和反思，另一方面也是激励自己——没有什么问题是定位不了的，要有必胜的决心！——是为记。

问题描述

我们系统有个可用性监控脚本，用python写的，定时请求系统的几个关键接口，根据接口响应分析下系统是否可用。脚本上线之后，有一个很奇怪的小问题出现了（就是周一早上我迷迷糊糊看邮件发现的）。零星有告警邮件说，接口响应code_error。根据时间去定位了一下，发现具体的响应说签名不正确。这个问题奇怪的地方就在于，签名不正确这种错误一般是在开发过程中出现的对吧，有可能是签名方式出错了什么的。脚本是我这边经手的，开发过程结束后，可以保证签名方式的正确性，包括秘钥也是正确的，一个有力的证据就是——每次告警之后很快又恢复正常。如果签名方式或者秘钥错误的话，是肯定不会恢复正常的。那这就奇怪了，对一个接口来说，签名方式是固定的，调用方的秘钥也是固定的，为什么会偶尔出现签名不对的情况呢？

抽丝剥茧

第一步，怀疑监控脚本签名错误

由于接口是旧有的使用很久了，而监控脚本是最近新加的，我本能地认为，一定是监控脚本哪里写错了。静下心来重新看了一遍脚本签名的逻辑，真的被我发现了问题。

        id = int(time.time())
        if only_id:
            signStr = util.sign_md5(caller, {'id':id }, secret, connector, key_in_sign)
            data = [data]
        else:
            signStr = util.sign_md5(caller, data, secret, connector, key_in_sign)                
        request_data = {
            "id": int(time.time()),
            "client": {
                'caller': caller,
                'ex': ''
            },
            "data": data,
            "sign": signStr,
            "encrypt": "md5",
        }

机智如我，很快想到，在极端情况下，参与签名的id和request_data中的id会不一样，这样服务端根据拿到的数据签名，结果就会和脚本中的签名不一样。问题找到了好开心呀O(∩_∩)O哈哈哈~我心情愉悦地大笔一挥改了一行代码(将”id”: int(time.time())改成”id”: id)然后以迅雷不及掩耳之速将改好后的脚本发给运维同学，同时傲娇地说：“code_error这个是监控脚本的问题，我改好了，你重新部署一下吧”。运营同学闻听此言也欢快地跑去部署了新的脚本。我们俩乐滋滋地觉得，终于不会再有烦人的告警邮件过来了。

事实证明我们还是太天真了。新的脚本上线之后，仍然时不时收到code_error的告警邮件。事实上从日志中看，服务端响应invalid_sign的次数不仅没有减少或消失，还增多了。

第二步，怀疑服务端处理问题

在花费了大量时间反复确认监控脚本真的是没问题之后，终于，我把怀疑的目光投向了服务端。由于服务端的日志记录太精简，几乎得不到什么信息(所有的信息就是请求XXX，响应invalid_sign，由于响应内容没有唯一标识，甚至我都不能确定请求与响应之间是否对应得起来)。

于是，我首先将响应日志改造了一下，加上了必须的信息。在这里啰嗦一下，打印日志真的是门技术活，打印太多不行，打印太少也不行，怎么样打印出刚刚好的日志需要好好研究一下。然后，我找到服务端验签的逻辑，仔细阅读了一下。看来看去，我开始怀疑起服务端签名库是不是有点问题。这个怀疑既有道理又没有道理。有道理在，确实有一些签名库不靠谱，没准就被我们碰上了。没道理在，这个签名库是公司很流行的一个框架中带的，很多团队都在用，没听说有问题啊。反正也看不出别的问题，就死马当做活马医吧。除了这个问题之外，我有小小地怀疑了一下是不是并发造成的问题。但没有往深处挖，跟最开始不想怀疑服务端一样，我默认服务端的框架是成熟的没有问题的。

这里剧透一下，最后真的是并发的问题。遗憾的是这是在上线了一个版本添加了日志之后定位的。

第三步，根据监控日志和服务端日志定位问题

刚好第二天有个版本上，在验签逻辑那里添加了一行代码记录不包含秘钥的待签名原文后，代码上线了。然后就是等，等code_error的告警过来。没过多久果然code_error如约而至。赶紧喊运维同学拿监控日志过来，我再搜索线上服务器对应的日志，一比对，问题就很明显了。
监控脚本日志：

[2015-05-19 15:00:50] 请求时间:2015-05-19 15:00:49.011157, 请求api地址：http://XXXXXX， 响应时间：0.0828s，httpCode:200, 请求结果状态:code_error,错误信息:{"id":1432018849,"state":{"code":500,"msg":"invalid_sign"},"data":[]},请求内容：{"encrypt": "*", "client": {"caller": "*_monitor", "ex": ""}, "data": [{"gameId": "*", "platfromId": "2", "chIdentification": "*"}], "id": 1432018849, "sign": "6e631228302fbd789246c72e6a10ee9e"}，spendTime (1.09033679962)
[2015-05-19 15:00:50] FAIL - .***_result=code_error | time=1.11 status=2(为了保密省去若干信息)

id是请求的唯一标识，根据这个唯一标识在服务端日志搜索却有不一样的发现：

[2015-05-19 15:00:49] INFO ~ * request: {"encrypt": "*", "client": {"caller": "*_monitor", "ex": ""}, "data": [{"gameId": "*", "platfromId": "2", "chIdentification": "*"}], "id": 1432018849, "sign": "6e631228302fbd789246c72e6a10ee9e"}
[2015-05-19 15:00:49] INFO ~ * request: {"id":"1432018849943","client":{"caller":"*serve","ex":{}},"encrypt":"*","sign":"e85ec9a57b633cf9b0c5a772f5bdd723","data":[{"gameId":*,"platfromId":2,"chIdentification":"*"},{"gameId":*,"platfromId":2,"chIdentification":"*"}]}
[2015-05-19 15:00:50] INFO ~ server端待签名字符串(不含秘钥)为：*serve1432018849943,md5签名结果为：e85ec9a57b633cf9b0c5a772f5bdd723
[2015-05-19 15:00:50] INFO ~ server端待签名字符串(不含秘钥)为：*serve1432018849,md5签名结果为：3c0ea83689fc65b8045cd15bfeeb809c

定睛一看，id为1432018849匹配的本该是*_monitor的caller，但是却匹配到了*serve的caller。自然而然地，id为1432018849的请求收到了invalid_sign的响应。监控脚本何其无辜啊！明明是服务端拿错了caller好不好！回过头来看服务端action的代码，果然发现了问题：

public class *Action extends Controller {
    private static Long id = (long) 0;
    private static String caller = "";

    public static void someMethod() {
        JsonObject request = getRequestData();
        try {
            //验证sign
            Long id = request.get("id").getAsLong();
            checkSign(request);
            /*
             *省略业务逻辑
             */            
            sendSuccess(id, caller, total, responseArray);
        } catch (Exception ex) {
            sendError(request.get("id").getAsLong(), caller, (long ) 500, "exception:" + ex.getMessage());
        }
    }

    /**
     * 获取请求数据
     * @return
     */
    private static JsonObject getRequestData() {
        ……
        JsonObject requestData = JsonUtils. parse(bodyStr);

        JsonObject client = requestData.get( "client").getAsJsonObject();
        caller = client.get("caller" ).getAsString();//对全局静态变量caller赋值        
        /**
         * 省略校验逻辑
         */
        return requestData;
    }

    /**
     * 加密校验
     * @param request
     */
    private static void checkSign(JsonObject request) {
        String signScerectKey = ...;//根据caller拿到秘钥
        // 服务端计算签名
        String sign = getSign(caller, String.valueOf(request.get("id").getAsLong()), signScerectKey);
        String authKey = request.get( "sign").getAsString();
        // 签名不一致响应invalid_sign
        if (!authKey.equals(sign)) {
            sendError(request.get("id").getAsLong(), caller, (long ) 500, "invalid_sign" );
        }
    }
    /**
     * 省略其他方法
     */
}

在计算签名的时候，参与签名的caller是拿的全局静态变量，而另一个参与签名的id却是从请求中获取的原始数据。两个不同的请求方并发请求时，稍微靠后的请求caller覆盖了之前的caller，当靠前的请求运行到计算签名的时候，拿到的实际上是靠后请求的caller。自然，计算出的结果一定和请求中的签名不一致。查了查这些天code_error告警时的日志，发现*_monitor和*serve都是同时请求过来的。事实上，除了对监控请求返回了invalid_sign之外，*serve也被监控请求干扰了若干次。估计因为量不多，所以请求方并没有找我们Σ( ° △ °|||)︴

真相大白

真相大白之后，首先就是改action代码啦。把两个全局静态变量干掉，在每次需要用到caller的时候都从请求中获取，虽然麻烦了点，但保证不会拿窜位了。然后认真地跟运维同学说，问题真的定位到了，不是脚本的问题，是服务端代码的问题。运维同学高兴地表示，监控脚本还是有那么点用的嘛~(^o^)/~

每次必写的总结

这个问题从发现到解决前前后后花了差不多两天的时间。而且期间涉及到运营同学重新部署脚本一次，应用服务添加日志升级一次，和我反反复复的查看源码和日志若干次，算得上一个复杂的问题了。虽然最后定位到的问题也没有很高深(就是不能够乱用全局变量啦，真的不高深)，但鉴于它带给我很深的心理创伤——各种百思不得其解和将要怀疑一切的分裂感觉，我觉得还是很有必要认真总结一下的：

• 查问题不要犯经验主义的错误，不要总是感觉“这里应该不会有问题”然后就略过，很有可能略过的就是问题所在。
• 打印日志需要谨慎再谨慎，该打的要打，不该打的坚决不能打。针对文中提到的action，正常流程下当然可以省略很多日志，但是在出现签名不对这样的问题时，还是应该将对应请求的id和caller等能唯一标识请求的信息打印下来，因为这些信息查问题时都会需要。
• 基础要扎实，java全局静态变量的定义是什么，用了的好处和坏处有哪些，项目中该用还是不该用，这些如果很熟练的话相信定位问题的时间也会缩短。
• 最后，还是不要用全局静态变量啦！