致命的巧合：一次结算异常排查总结

一 异常现象.

1、2018-04-02 16:00左右，实验田的两台机器手动部署基线、拉取索引、追消息并接流。
2、第二天接到大量广告主投诉，投诉内容是广告的结算价格远大于自己的出价
3、通过pv日志查询，发现存在大量pv的orgprice值（广告主出价）被错误地写成score值（广告海选质量分），而score在数值上通常是orgprice的几百倍
4、所有出问题的流量（后简称异常流量）都来源于两台实验田机器中的一台（后简称异常机器）
5、接到异常投诉时，异常已经消失，消失时间点为线上机器每天早上例行切换索引的时间，即2018-04-03 06:00左右

二 排查过程.

2.1 怀疑不合规的操作.

分析：由于出问题的实验田机器为手动部署基线，且所有异常流量均来自于实验田机器中的其中一台，因此第一怀疑是手动操作流程有问题。
矛盾点：两台实验田机器进行了同样的操作，若为操作不合规导致，则现象上应该是两台机器都有问题，而不是其中一台有问题而另一台正常
排查：通过linux的history命令查询了手动部署机器全过程使用的命令，没有发现不合规的操作。

2.2 怀疑数据拉取异常.

分析：由于操作没有不合规，且问题在切换索引之后就消失了，因此怀疑是2018-04-02 16:00至2018-04-03 06:00期间，异常机器的数据由于“未知因素”出现异常
矛盾点：数据异常的原因没有合理的解释
排查：通过pv日志获取异常流量的请求串，对备份索引（即出问题时间段内的异常机器使用的索引）进行查询，发现数据正常

2.3 怀疑进程中存在bug.

分析：由于切换索引的过程中会切换数据、重启服务进程，2.2中的结论认为数据大概率不存在问题，那么问题可能是进程中存在bug。现象上，score和orgprice字段的数值一样，而这两个字段都来源于payload，且位置相邻，因此怀疑是进程在读取数据时将这两个字段当作一个字段进行处理。
矛盾点：实验田机器和线上的基线完全一致，而线上自从新版索引内核上线以来已经有1.5个月，线上都没有出现类似问题
排查：重点分析新版检索内核读取payload数据相关的代码，果然发现了一些端倪

三 致命的巧合.

3.1 artis内核中的一个诡异设计.

3.1.1 预备知识

在说明artis内核的这个诡异设计之前，我们先说明一下payload的字段是如何被读取的。
假设索引配置的payload中有三个字段，按照在indexlib manager配置中的定义顺序分别是name、gender、age

{
  name,
  gender,
  age,
}

那么检索内核在初始化时，会按照定义顺序给每个字段一个offset，存在一个map中（后简称name2offset_map）

field_name	offset
name	0
gender	1
age	2

在物理存储上，也是按照定义顺序进行存储

我们想读取一个数据时，先通过name在name2offset_map查到offset，然后在用offset到payload的对应位置读取数据。

3.1.2 artis内核的设计.

还是上面的场景，artis内核进行了一个很诡异的设计。
当我们需要查询一个字段时，我们需要先到indexlib manager的一个map中（后简称name2id_map）用name获取到一个id，然后在到另一个map
中（后简称id2name_map）在通过id反查得到name，再到name2offset中通过name得到offset。
这个设计看上去直觉上的一个问题就是，为什么要用name2id + id2name，这不是重复操作么？这个问题的答案是：为了保证接口的兼容性，也是无奈之举，再次不做赘述。这个还不是最诡异的设计，毕竟这样设计不存在功能问题。
最诡异的地方在于，在通过name获取id时，id的分配机制是：每个name第一次被访问时，动态的分配id，该id会随着出现的name的种类自增。简单来说就是，当某个字段没有被读取之前，是不存在id的，当他被第一次读取的时候，才会分配一个id。
举例说明，还是3.1.1里面的配置，假设业务代码中访问字段的顺序是gender、age、name，那么，name2id_map、id2name_map、name2offset分别是

field_name	id
gender	0
age	1
name	2

id	field_name
0	gender
1	age
2	name

field_name	offset
name	0
gender	1
age	2

物理存储方式不变。
我们看到，id其实表示的是业务代码中对各个字段“第一次访问”的顺序，在索引数据中并没有实际含义，只是一个用来维护映射关系的中间层

3.1.3 设计漏洞

我们先来看下分配id的代码

int32_t CPayloadHelper::getPayloadIndex(const char* name) {
  if (name == NULL) {
    return -1;
  }
  typeof(name_idx_map_.begin()) it = name_idx_map_.find(name);
  if (it == name_idx_map_.end()) {
    name_idx_map_.insert(pair<string, int32_t>(name, name_cur_idx_));
    idx_name_map_.insert(pair<int32_t, string>(name_cur_idx_, name));
    return name_cur_idx_++;
  }
  return it->second;
}

总结来看就是，先用name查map，若存在，则直接返回对应的id；若不存在，则将name_cur_idx_的值分配给这个name，加入到map中，并且将name_cur_idx_自增1。
这样的问题在于，当多个线程并行访问时，会出现错乱。假设有2个线程thread0、thread1，同时“第一次”访问字段score和orgprice，会出现如下场景：

结果是score和orgprice都会映射id为0，具体现象是这样两个字段会被当作同一个字段处理。

3.2 业务代码中的线程安全隐患

有了上面的分析，我们就需要带着目的重新审视业务代码，看看有没有出现多个线程使用同一个indexlib manager的可能性。
先简单介绍下cpm和cpc流量的检索流程
1、cpm
SPF_handler：打分（当前pv首次试图访问score、orgprice访问score字段）、排序、海选
next_query_handler：判断doc是否足够，决定是否需要新一轮检索
merge_handler：检索完成后，通过docid从索引中读取必要的数据，方面后续向上游返回（如之前没访问过score、orgprice字段，则此处为第一次访问score、orgprice）
2、cpc
SPF_handler：打分（当前pv首次试图访问score、orgprice字段）、排序、海选
first_rank_handler：初选打分、排序、初选
next_query_handler：判断doc是否足够，决定是否需要新一轮检索
merge_handler：检索完成后，通过docid从索引中读取必要的数据，方面后续向上游返回（如之前没访问过score、orgprice字段，则此处为第一次访问score、orgprice）

上述检索流程中，在SPF_handler和next_query_handler内部，会对indexlib manager进行锁定和释放。具体来说，就是hanlder开始运行之前，会从indexlib manager池中获取一个实例，然后handler运行结束后，会将这个实例放回池子。但是业务代码中存在一个重大的漏洞，就是handler结束后，虽然将实例放回了池子，但是仍然保留了对这个实例的引用指针。这个指针将会传递给后面的handler（例如merge_handler）。此时，若有另外一个线程又从池子中获取同一个实例，则这个实例会被两个线程同时引用，引入了线程安全的隐患。

但是，这个隐患会导致3.1.3里面描述的问题么？答案是未必。如上文所述，SPF_handler首次试图访问score、orgprice字段，那么在此之后的merge_handler将不再构成“第一次访问”，而3.1.3中的问题只会在“同时第一次访问”的场景下出现。因此只有绑定了同一个indexlib manager实例的两个线程同时运行到SPF_handler时，才会出现score和orgprice错乱的问题。可是SPF_hanlder在运行前会试图从池子中获取实例（获取过程时线程互斥的），也就是说，两个线程的SPF_handler不可能获取到同一个实例，仍然不会触发3.1.3里面描述的漏洞。
问题查到这里陷入了僵局——

3.3 cpm打分中的恶意：细节是魔鬼

（接上文）问题查到这里陷入了僵局——artis索引内核中的漏洞看上去不会导致被触发——直到我发现了cpm打分中的一个细节，一个cpm流量特有的逻辑。
cpm广告要求海选结果的数量为200，因此，当我们的候选集都不足200时，是否就没有必要打分、排序了呢？我们只需要把查出来的广告都返回就好了。从业务功能上，这个结论是没问题的，但是正是这个设计成为了压死骆驼的最后一根稻草——最终触发了漏洞。cpm流量的SPF_handler在打分前会进行一个判断，若候选集数量小于200，则不打分（也就不会访问score、orgprice）直接跳转后面的逻辑（如merge_handler）,也就是说，score、orgprice字段“第一次被访问”的可能性被保留到了merger_handler。如果此时，被SPF_handler释放的indexlib manager实例被另一个线程的SPF_handler锁定并且进行打分，就满足了“两个线程同时第一次访问同一实例中的字段score和字段orgprice”，3.1.3中的漏洞就会被触发。一旦漏洞被触发，则所有使用异常实例进行处理的pv的score和orgprice字段的值都会错乱，直到进程重启（每次重启重新进行动态分配）。

3.4 这是一个巧合

触发这个bug的条件有：
1、某个cpm流量（thread0）召回的候选集数量小于200
2、thread0中merge_handler中使用的indexlib manager实例被另一个线程（thread1）的SPF_handler锁定
3、这个实例还没有被使用过
4、thread0对score、orgprice的第一次访问和thread1对score、orgprice的第一次访问同时发生
5、thread0和thread1按照3.1.3图中描述的流程进行线程切换
一般在晋城启动几ms之后，所有的实例就都被使用过了，因此，只有在这几ms之内，刚好满足了上述5个条件，漏洞才会被触发，这就解释了线上为什么没有出现问题。这样看来，实验田的这次操作是“中奖”了。
我写了一个程序去模拟条件5的触发概率（见附录一）,测得触发概率为万分之15左右，真实的触发概率一定还会比这个低很多。

四 经验总结

1、该发生的bug不管概率多小，都一定会发生；而且概率越小，排查的周期越长，可能带来的影响越大。因此，在日常开发中一定要谨慎谨慎再谨慎，对于多线程问题，预防胜于解决。
2、在本次排查过程中，仍然烦了我经常容易犯的错误：去怀疑“几乎不可能”的事情。比如，我怀疑过linux系统mmap机制出了问题，也怀疑过cpu电平由于宇宙射线的干扰发生了反转（这个事情我只从新闻上看到过，一次）。本质上，对不可能的事情进行怀疑是对现实问题的逃避心理。我们应该遵循大概率的“理性”，按照类似本文第二章中的分析方法，逐步排查，缩小范围。

附录一

#include <pthread.h>
#include <string>
#include "newsn/IndexlibManager.h"
#include "newsn/IndexField.h"
#include "newsn/PayloadHelper.h"
void* TestBody(void* arg);
int main(int argc, char* argv[]) {
  std::string index_path = argv[1];
  std::string index_conf = index_path + "/artis.xml";
  uint32_t round = 100;
  while (round--) {
    indexlib::CIndexlibManager *index_manager =
      new indexlib::CIndexlibManager();
    int32_t ret = index_manager->init(index_conf.c_str(),
                        index_path.c_str(),
                        "payload");
    if (ret != 0) {
      printf("init index_manager failed.\n");
      return -1;
    }
    indexlib::CIndexField* index_field =
                index_manager->getIndexField("indextag");
    if (index_field == NULL) {
      printf("get index field failed.\n");
      return -2;
    }
    indexlib::CPayloadHelper *payload_helper =
              index_field->getPayloadHelper();
    if (payload_helper == NULL) {
      printf("get payload helper failed.\n");
      return -3;
    }
    pthread_t pid0 = -1;
    pthread_t pid1 = -1;
    pthread_create(&pid0, NULL, TestBody, payload_helper);
    pthread_create(&pid1, NULL, TestBody, payload_helper);
    void* ret0 = NULL;
    void* ret1 = NULL;
    pthread_join(pid0, &ret0);
    pthread_join(pid1, &ret1);
    if (((int64_t)ret0) == -1 ||
        ((int64_t)ret1) == -1) {
      printf("debug!!!\n");
    }
  }
  return  0;
}

void* TestBody(void* arg) {
  int64_t ret = 0;
  indexlib::CPayloadHelper *payload_helper =
    reinterpret_cast<indexlib::CPayloadHelper*>(arg);
  int32_t score_idx = payload_helper->getPayloadIndex("score");
  int32_t orgprice_idx = payload_helper->getPayloadIndex("orgprice");
  if (score_idx == orgprice_idx) {
    ret = -1;
  }
  return (void*)ret;
}