记一次 BUG 的排查过程(Redis)

1,367 阅读6分钟
原文链接: leehao.me

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

存在问题的程序使用了 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;
}

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

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

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

时间 客户端A 客户端B
T1 WATCH abcd
T2 SET abcd 1
T3 WATCH abcd
T4 GET abcd
T5 MULTI
T6 SET abcd 2
T7 EXEC

客户端A对键 abcd 执行WATCH命令后,客户端B对键 abcd 执行更新操作。接下来客户端A继续执行WATCH,虽然第二次执行WATCHEXEC期间,没有客户端对键进行修改,但执行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日再次执行MULTIEXEC时,便会出现执行事务失败的情况,EXEC返回 nil。

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

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

小结

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

参考资料

  1. redis.io/topics/tran…
  2. redis.io/commands/wa…
  3. redis.io/commands/un…
  4. redis.io/commands/di…
  5. redisbook.readthedocs.io/en/latest/f…