【线上故障】通过系统日志分析和定位-系统日志检测

你好，我是雨乐!

在之前的文章中，我们有讲到如何定位内存泄漏和GDB调试-从入门实践到原理。今天，借助本文，来分享另外一种更为棘手的线上问题解决方案-如何在没有coredump文件的情况下，定位程序崩溃原因。

前言

一个优秀的程序员，编码能力和解决问题的能力必不可少。编码能力体现的是逻辑思维能力，而解决问题的能力不仅仅依靠自己经验的积累，更需要一定的敏锐嗅觉和使用其他方式解决问题的能力。管他黑猫白猫，抓住老鼠就是好猫。

在日常的项目开发中，根据Bug产生的时机和环境，我们可以将Bug细分为以下几种：

线下缺陷：此阶段发生在上线前。主要在测试阶段，由开发人员在自测过程中或者有测试人员发现
线上问题：此阶段发生在上线后，也就是在正式环境或者生产环境。主要是不符合产品的需求逻辑，可能会影响用户体验
线上故障：这个阶段是最严重的，对公司的收益、用户体验都会造成影响，主要为服务不可用等

在本文的示例中，我们针对的第三个阶段，即线上故障进行定位和分析的一种方式，希望借助本文，能够对你的故障定位能力有一定的帮助。

背景

早上到了公司，正在愉快地摸鱼，突然企业微信来了条报警，某个核心服务重新启动了。

于是，快速打开iterm，通过跳板机登录线上服务器，第一时间，查看有没有coredump文件生成:

ll /www/coredump/
total 0

竟然没有coredump文件，当时心情是这样的：

当时第一反应是有人手动重启了，于是在组内群里问了下，没人动线上，看来问题比较麻烦。

排查

既然没有coredump文件产生，且没有人手动重启服务，只能分析下系统日志，看看能得到什么线索。

通过在系统日志中，查找进程名来获取进程发生错误时候的日志信息。

grep xxx /var/log/messages

kernel: xxx[11120]: segfault at 7f855009e49f ip 0000003ab9a75f62 sp 00007fcccd7f74c0 error 4 in libc-2.12.so[3ab9a00000+18b000]

在上面的信息中：

xxx 为进程名，后面括号中的11120代表当时的线程id7f855009e49f为出错时候的地址
0000003ab9a75f62为发生错误时指令的地址
00007fcccd7f74c0 为堆栈指针
3ab9a00000为libc在此程序中映射的内存基址
segfault at和error 4这两条信息可以得出是内存读出错

其中，内核对error的定义如下：

/*
 * Page fault error code bits:
 *
 *   bit 0 ==  0: no page found 1: protection fault
 *   bit 1 ==  0: read access  1: write access
 *   bit 2 ==  0: kernel-mode access 1: user-mode access
 *   bit 3 ==    1: use of reserved bit detected
 *   bit 4 ==    1: fault was an instruction fetch
 *   bit 5 ==    1: protection keys block access
 */
enum x86_pf_error_code {
 X86_PF_PROT =  1 << 0,
 X86_PF_WRITE =  1 << 1,
 X86_PF_USER =  1 << 2,
 X86_PF_RSVD =  1 << 3,
 X86_PF_INSTR =  1 << 4,
 X86_PF_PK =  1 << 5,
};
#endif /* _ASM_X86_TRAPS_H */

error 4代表用户态程序内存访问越界。

好了，通过上述内核日志，我们基本可以得出如下结论：

名为xxx的进程中，线程id为11120发生了用户态程序内存访问越界，且最终core在了libc-2.12.so中。原因基本确定，现在我们开始定位问题。

初步定位

使用ldd命令，查看可执行程序的依赖：

ldd xxx
 linux-vdso.so.1 =>  (0x00007ffedb331000)
 librt.so.1 => /lib64/librt.so.1 (0x0000003aba200000)
 libdl.so.2 => /lib64/libdl.so.2 (0x0000003ab9600000)
 libstdc++.so.6 => /usr/lib64/libstdc++.so.6 (0x0000003abce00000)
 libm.so.6 => /lib64/libm.so.6 (0x0000003aba600000)
 libc.so.6 => /lib64/libc.so.6 (0x0000003ab9a00000)
 /lib64/ld-linux-x86-64.so.2 (0x0000562e90634000)
 libpthread.so.0 => /lib64/libpthread.so.0 (0x0000003ab9e00000)
 libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x0000003abc200000)

在上一节中，我们得到了程序发生错误时指令的地址(0000003ab9a75f62)以及libc-2.12.so在进程中的基址(3ab9a00000)，下面我通过objdump命令来进行分析。

反汇编

通过下述命令，得到libc-2.12.so汇编结果(因为内容较多，我们将其重定向输出到一个临时文件)

objdump -tT /lib64/libc-2.12.so > ~/info

查找汇编语句

Libc-2.21.so是个基础库，其内容多达58m，很难直接从中获取有用信息。

ll info
-rw-r--r-- 1 root root 58369282 Jan 28 10:14 info

为了快速定位错误点，我们抓取跟错误点地址3ab9a75f62相关的命令(为了获取上下文，所以grep了部分)

objdump -tT /lib64/libc-2.12.so | grep 3ab9a75

输出如下：

0000003ab9a75100 l     F .text 0000000000000176              enlarge_userbuf
0000003ab9a756b0 l     F .text 000000000000011b              ptmalloc_lock_all
0000003ab9a757d0 l     F .text 00000000000000b6              ptmalloc_unlock_all
0000003ab9a75890 l     F .text 00000000000000c1              ptmalloc_unlock_all2
0000003ab9a75960 l     F .text 0000000000000003              __failing_morecore
0000003ab9a75a20 l     F .text 00000000000000da              sYSTRIm
0000003ab9a75b00 l     F .text 000000000000029d              mem2chunk_check
0000003ab9a75da0 l     F .text 00000000000000e0              malloc_printerr
0000003ab9a75e80 l     F .text 0000000000000541              malloc_consolidate
0000003ab9a75280 l     F .text 0000000000000187              _IO_str_seekoff_internal
0000003ab9a75970 l     F .text 000000000000006b              __malloc_check_init
0000003ab9a75410 l     F .text 00000000000001aa              _IO_str_overflow_internal
0000003ab9a759e0 l     F .text 0000000000000031              __malloc_usable_size
0000003ab9a75020 l     F .text 0000000000000062              _IO_str_underflow_internal
0000003ab9a750b0 l     F .text 000000000000002b              _IO_str_finish
0000003ab9a75090 l     F .text 0000000000000012              _IO_str_count
0000003ab9a755c0 l     F .text 00000000000000ae              _IO_str_init_static_internal
0000003ab9a750e0 l     F .text 0000000000000015              _IO_str_pbackfail_internal
0000003ab9a759e0  w    F .text 0000000000000031              malloc_usable_size
0000003ab9a75020 g     F .text 0000000000000062              _IO_str_underflow
0000003ab9a750e0 g     F .text 0000000000000015              _IO_str_pbackfail
0000003ab9a75410 g     F .text 00000000000001aa              _IO_str_overflow
0000003ab9a75670 g     F .text 000000000000001d              _IO_str_init_readonly
0000003ab9a75690 g     F .text 0000000000000012              _IO_str_init_static
0000003ab9a75280 g     F .text 0000000000000187              _IO_str_seekoff
0000003ab9a750e0 g    DF .text 0000000000000015  GLIBC_2.2.5 _IO_str_pbackfail
0000003ab9a75690 g    DF .text 0000000000000012  GLIBC_2.2.5 _IO_str_init_static
0000003ab9a759e0  w   DF .text 0000000000000031  GLIBC_2.2.5 malloc_usable_size
0000003ab9a75020 g    DF .text 0000000000000062  GLIBC_2.2.5 _IO_str_underflow
0000003ab9a75280 g    DF .text 0000000000000187  GLIBC_2.2.5 _IO_str_seekoff
0000003ab9a75410 g    DF .text 00000000000001aa  GLIBC_2.2.5 _IO_str_overflow
0000003ab9a75670 g    DF .text 000000000000001d  GLIBC_2.2.5 _IO_str_init_readonly

为了进一步定位问题点，我们使用objdump命令并指定起始点

objdump -d /lib64/libc-2.12.so --start-address=0x3ab9a75000 | head -n2000 | grep 75f62

输出如下：

3ab9a75ec8: 0f 85 94 00 00 00     jne    3ab9a75f62 <malloc_consolidate+0xe2>
  3ab9a75f62: 48 8b 43 08           mov    0x8(%rbx),%rax

基本能够确定在进行malloc的时候，出现了问题。

精准定位在上节中，我们定位到原因是malloc导致，但是代码量太大，任何一个对象底层都有可能调用了malloc(new也会调用malloc)，所以一时半会，不知道从哪下手。

为了定位原因，采用最近定位法，分析最近一次上线的代码改动，这次改动，将之前的redis Sentinel改为了redis cluster，而redis 官方没有提供cluster的client，所以自己手撸了个client，而在这个client中调用malloc顺序如下：

-> Init
--> redisClusterInit
----> calloc
------> malloc

好了，到此，进程崩溃的代码点基本定位了，下面我进行原因分析。

原因分析

程序对RedisClusterClient进行初始化的地方有两个：

程序启动的时候
当连接断开的时候

因为程序已经运行了一段时间，所以第一条基本不成立，那么我们看下本次改动使用的命令之一ZRangeByScore的实现：

void RedisClusterClient::ZRangeByScore(std::string& key, std::string min, std::string max,
                            std::vector<std::string> *vals,
           bool withscores,
                            std::string *msg) {
  // ....
  redisReply *reply = static_cast<redisReply*>(
        redisClusterCommandArgv(cc_, argv.size(), &(argv[0]), &(argvlen[0])));

  if (!reply || reply->type != REDIS_REPLY_ARRAY) {
      // ...
      redisClusterFree(cc_);
      cc_ = nullptr;
      Init(host_, password_, &connect_timeout_, &op_timeout_, msg);
    }

    return;
  }
  // ...
}

单纯这块代码，是不会有问题的，所以需要把使用这块代码的都考虑进来。我们重新理下请求的调用链：

-> Load
--> GetHandler
----> GetSession
------> GetRedisClient

重新进行代码分析，发现在特定条件下，GetRedisClient可能会被多个线程同时调用，如果不进行Init的话，一切正常，而当一个线程Init的时候，恰好另外一个线程进行读，因此引起了访问一个已经释放的内存地址，所以导致了进程崩溃。

这种情况发生的概率很低，很难重现。毕竟连接突然断开的同时，又有一个线程在同时访问，在线上还是很难出现(当然可以在线下通过tcpkill进行模拟，这就是另外一回事了)，总体来说，还是比较幸运，能够迅速定位。

问题解决

在整个bug的分析和解决过程中，定位segfault是最困难的地方，如果知道了segfault的地方，分析原因，就相对来说简单多了。当然，知道了崩溃原因，解决就更不在话下了😃。

程序崩溃，基本上都跟内存有关，无非是越界、访问无效地址等。在本例中，就是因为访问一个已经释放的内存地址而导致的，根据代码的实际使用场景，在对应的地方，加锁，线上灰度，然后全量上线。

结语

遇到线上问题，一定不能慌，如果是频繁的coredump或者重启，那么就先回滚到上个版本，然后再分析和解决问题。

如果有生成coredump，那么可以使用gdb进行调试，查看coredump产生位置，然后根据上下文分析产生coredump的原因，进而解决问题。

如果没有生成coredump，这个时候，就需要借助其他方式，比如先查看是否因为OOM导致的进程消失，这个时候需要查看部署本服务的其他进程的内存占用情况;如果排除了OOM原因，那么可能就是其他原因了，这个时候，可以借助系统日志来初步定为进程消失的原因，比如本例中的segfault，然后采用对应的方式来解决问题。

好了，本期的文章就到这，我们下期见!