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

2022-08-25 15:59:03 浏览数 (1)

你好,我是雨乐!

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

前言

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

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

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

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

背景

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

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

代码语言:javascript复制
ll /www/coredump/
total 0

竟然没有coredump文件,当时心情是这样的:

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

排查

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

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

代码语言:javascript复制
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代表当时的线程id
  • 7f855009e49f为出错时候的地址
  • 0000003ab9a75f62为发生错误时指令的地址
  • 00007fcccd7f74c0 为堆栈指针
  • 3ab9a00000为libc在此程序中映射的内存基址
  • segfault at和error 4这两条信息可以得出是内存读出错

其中,内核对error的定义如下:

代码语言:javascript复制
/*
 * 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命令,查看可执行程序的依赖:

代码语言:javascript复制
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汇编结果(因为内容较多,我们将其重定向输出到一个临时文件)

代码语言:javascript复制
objdump -tT /lib64/libc-2.12.so > ~/info

查找汇编语句

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

代码语言:javascript复制
ll info
-rw-r--r-- 1 root root 58369282 Jan 28 10:14 info

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

代码语言:javascript复制
objdump -tT /lib64/libc-2.12.so | grep 3ab9a75

输出如下:

代码语言:javascript复制
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命令并指定起始点

代码语言:javascript复制
objdump -d /lib64/libc-2.12.so --start-address=0x3ab9a75000 | head -n2000 | grep 75f62

输出如下:

代码语言:javascript复制
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顺序如下:

代码语言:javascript复制
-> Init
--> redisClusterInit
----> calloc
------> malloc

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

原因分析

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

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

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

代码语言:javascript复制
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;
  }
  // ...
}

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

代码语言:javascript复制
-> Load
--> GetHandler
----> GetSession
------> GetRedisClient

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

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

问题解决

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

0 人点赞