记一次 BUG 的排查过程

最近生产上上线了一个新的功能，在业务人员使用过程中，通过查看日志我们发现一个诡异的问题。这篇文章记录一下这个问题的排查过程以及解决方法。

存在问题的程序使用了 C 语言的 Redis 客户端 hiredis 来连接和操作 Redis。由于处于分布式的环境，所以我们使用了 Redis 的事务的特性，以避免多个客户端同时对 Redis 数据进行更改导致数据错乱的情况出现。有关 hiredis 的使用以及 Redis 事务特殊的介绍，可以参考文章《Redis C 语言客户端 hiredis 的使用》，以及《Hiredis 实现 Redis 流水线》。

程序原始代码如下：

void GFRedisClient::QueryRowsByFields(const char *key,                                      map<string, string> &mapField2Value,                                      vector<map<string, string> > &outRecords)
{    if (!key || strlen(key) <= 0) {
        KSBLog(WARN, "传入的服务代码为空");        return;
    }    // 获取Redis连接
    redisContext *ctx = CreateContext();    if (ctx == NULL) {
        KSBLog(WARN, "查询二维表出错，无法获取Redis连接，服务：%s", key);        return;
    }    // 监控二维表数据
    SendWatch(ctx, key);    // 取出指定记录
    vector<string> vecRecordRowIds;
    GetSpecRecords(ctx, key, mapField2Value, vecRecordRowIds);    if (vecRecordRowIds.empty()) {
        KSBLog(INFO, "从Redis查找不到指定条件的记录，服务：%s", key);
        ReleaseContext(ctx);        return;
    }    // 以事务实现
    int pipelineCount = 0;
    SendMulti(ctx, pipelineCount);    // 取出字段名称
    SendQueryFields(ctx, key, pipelineCount);    // 取出指定记录
    SendQuerySpecRecords(ctx, key, vecRecordRowIds, pipelineCount);    // 执行事务
    SendExec(ctx, pipelineCount);    // 处理返回结果
    ProposeQueryRows(ctx, key, pipelineCount, outRecords);    // 归还连接
    KSBLog(INFO, "查询二维表归还Redis连接，服务：%s", key);
    ReleaseContext(ctx);
}

这段代码的主要功能是从 Redis 中查询指定二维表记录。由于需要使用 Redis 的流水线事务的特性，而一些 Redis 命令操作依赖于前面 Redis 命令执行的结果，因此我们使用了 Redis 的 WATCH命令，以监控指定的 Redis 有没被更改。如果键被更改过，则执行EXEC命令会失败，返回nil；如果键没有被更改，则执行EXEC命令会返回正常结果。
上面的这段代码已经运行几个月了，期间没有发现问题。

最近在生产上，我们通过查看异常日志，观察到一个异常的情况。异常日志输出如下：

DEBUG|2017-12-13 11:30:38 -185|gfredis.cpp(430)-<ProposeQueryRows>: 执行流水线命令返回，类型：5，返回结果：OK，返回的子结果：0
DEBUG|2017-12-13 11:30:38 -185|gfredis.cpp(430)-<ProposeQueryRows>: 执行流水线命令返回，类型：5，返回结果：QUEUED，返回的子结果：0
DEBUG|2017-12-13 11:30:38 -185|gfredis.cpp(430)-<ProposeQueryRows>: 执行流水线命令返回，类型：5，返回结果：QUEUED，返回的子结果：0
DEBUG|2017-12-13 11:30:38 -185|gfredis.cpp(430)-<ProposeQueryRows>: 执行流水线命令返回，类型：4，返回结果：(null)，返回的子结果：0

最后一行是执行EXEC的输出日志，即执行EXEC命令失败了？！通过排查日志，可以确认在该时间点没有执行更新相同键的操作。那么，执行EXEC失败是什么导致的呢？
一开始，我们甚至还怀疑是不是 hiredis 的实现有 BUG，后来马上放弃了这个想法。Hiredis 出来已经很久了，而且应用广泛，理应不会出现如何低端的 BUG。
由于没有其他头绪，只能再次回到代码本身。代码包括以下的处理：

if (vecRecordRowIds.empty()) {
    KSBLog(INFO, "从Redis查找不到指定条件的记录，服务：%s", key);
    ReleaseContext(ctx);    return;
}

如果没能取出指定的记录，则会直接返回，而不会继续执行下面的MULTI和EXEC操作。这时灵光一现，会不会是这个原因导致的？为了确认，翻看了前两天的日志。真的发现了查打不到指定记录的日志：

INFO|2017-12-11 19:23:30 168|gfredis.cpp(254)-<QueryRowsByFields>: 从Redis查找不到指定条件的记录，服务：

顺着这个思路，我们使用 redis-cli 做了个试验，试验过程如下：

客户端A对键 abcd 执行WATCH命令后，客户端B对键 abcd 执行更新操作。接下来客户端A继续执行WATCH，虽然第二次执行WATCH到EXEC期间，没有客户端对键进行修改，但执行EXEC还是返回了 nil，即事务执行失败。

我们继续对 Redis 的源代码进行分析，可以看到 Redis 服务执行WATCH命令时，会判断客户端是否已监视过，如果已监视，则会直接返回。也就是说，在执行MULTI之前，同一个客户端执行多次WATCH跟第一次执行一次WATCH的效果是一样的。

/* Watch for the specified key */void watchForKey(redisClient *c, robj *key) {    list *clients = NULL;
    listIter li;
    listNode *ln;
    watchedKey *wk;    /* Check if we are already watching for this key */
    listRewind(c->watched_keys,&li);    while((ln = listNext(&li))) {
        wk = listNodeValue(ln);        if (wk->db == c->db && equalStringObjects(key,wk->key))            return; /* Key already watched */
    }    /* This key is not already watched in this DB. Let's add it */
    clients = dictFetchValue(c->db->watched_keys,key);    if (!clients) { 
        clients = listCreate();
        dictAdd(c->db->watched_keys,key,clients);
        incrRefCount(key);
    }
    listAddNodeTail(clients,c);    /* Add the new key to the list of keys watched by this client */
    wk = zmalloc(sizeof(*wk));
    wk->key = key;
    wk->db = c->db;
    incrRefCount(key);
    listAddNodeTail(c->watched_keys,wk);
}

这样，导致问题出现的原因就很清晰了。程序在12月11日执行了一次WATCH的命令且没有继续执行EXEC命令，这是由于从 Redis 无法查询到指定记录而造成的。接下来在12月13日，我们再次执行WATCH命令。但在12月11日至12月13日之间，存在其他客户端对相同的键执行了更新操作。因此，在12月13日再次执行MULTI和EXEC时，便会出现执行事务失败的情况，EXEC返回 nil。

为了修正这个问题，我们需要在从 Redis 查找不到指定记录返回前，添加执行UNWATCH命令的操作。（有关UNWATCH命令的介绍可以参考https://redis.io/commands/unwatch）这样一来，下次再开始执行事务时，不再受原来WATCH命令的影响。
修正后的代码如下：

if (vecRecordRowIds.empty()) {
    KSBLog(INFO, "从Redis查找不到指定条件的记录，服务：%s", key);
    SendUnWatch(ctx)；
    ReleaseContext(ctx);    return;
}

小结

这篇文章记录了一次 Redis 使用程序 BUG 的发现过程。由于 BUG 在测试环境较难重现，增加了 BUG 的修复难度。当然，如果一个 BUG 可以重现，修正就不在话下。在山重水复疑无路时，通过分析程序代码和日志，竟获得了柳暗花明又一村的意外结果。因此，在实际排查 BUG 的过程中，可以从尝试分析程序代码和日志入手，以便最终将问题修复。

参考资料

1. https://redis.io/topics/transactions

2. https://redis.io/commands/watch

3. https://redis.io/commands/unwatch

4. https://redis.io/commands/discard

5. https://redisbook.readthedocs.io/en/latest/feature/transaction.html

原文出处