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

大家好，我是玉乐！在上一篇文章中，我们讲了如何定位内存泄漏和GDB调试——从入门实践到原理。今天，我将借助这篇文章分享另一个比较难的在线问题解决方案——如何在没有coredump文件的情况下定位程序崩溃的原因。前言一个优秀的程序员，编码能力和解决问题的能力必不可少。编码能力体现的是逻辑思维能力，而解决问题的能力不仅取决于自身经验的积累，还需要一定的敏锐嗅觉和运用其他方法解决问题的能力。不管黑猫白猫，抓到老鼠就是好猫。在日常项目开发中，根据Bug产生的时机和环境，我们可以将Bug细分为以下几类：下线缺陷：这个阶段发生在上线之前。主要在测试阶段，线上问题是开发人员或测试人员在自测过程中发现的：这个阶段发生在上线之后，即在正式环境或生产环境中。主要原因是不符合产品需求逻辑，可能会影响用户体验。上线失败：这个阶段最为严重，会影响公司的收入和用户体验，主要是服务不可用。在这篇文章的例子中，我们针对第三阶段是在线故障定位分析的方法。希望本文能对您的故障定位能力有所帮助。背景早上到公司，开心的钓鱼。突然，企业微信传来告警，某核心服务重启。于是，赶紧打开iterm，通过跳板登录线上服务器，查看是否有第一时间生成的coredump文件：ll/www/coredump/total0没有coredump文件。我当时的心情是这样的：当时的第一反应是有人我手动重启了，于是在群里问了，结果网上没人动。看来问题比较麻烦。由于没有生成coredump文件，也没有人手动重启服务，我们只能分析系统日志，看看能得到什么线索。通过在系统日志中查找进程名，可以得到进程出错时的日志信息。grepxxx/var/log/messageskernel:xxx[11120]:segfaultat7f855009e49fip0000003ab9a75f62sp00007fcccd7f74c0error4inlibc-2.12.so[3ab9a00000+18b000]在上面的信息中，括号中的1是1和0的名字process:xxx表示当时的线程id7f855009e49f作为错误的地址0000003ab9a75f62是错误发生时指令的地址00007fcccd7f74c0是堆栈指针3ab9a00000是本程序中libc映射的内存基地址。segfaultat和error4这两条信息可以断定是内存读取错误其中，内核对error的定义如下：/**Pagefaulterrorcodebits:**bit0==0:nopagefound1:protection故障*位1==0：读访问1：写访问*位2==0：内核模式访问1：用户模式访问*位3==1：检测到保留位的使用*位4==1：故障是指令获取*位5==1：保护密钥阻止访问*/enumx86_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*/error4表示用户态程序内存访问越界。好了，通过上面的内核日志，我们基本可以得出以下结论：在名为xxx的进程中，线程id为11120，用户态程序内存访问超限，核心最终在libc-2.12。所以。原因基本确定了，现在开始定位问题。初始定位使用ldd命令查看可执行程序的依赖关系：lddxxxlinux-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。所以。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，很难直接从中获取有用的信息。llinfo-rw-r--r--1rootroot58369282Jan2810:14info为了快速定位错误点，我们抓取错误点地址3ab9a75f62相关的命令（为了获取上下文，所以grep部分)objdump-tT/lib64/libc-2.12.so|grep3ab9a75输出如下：0000003ab9a75100lF.text0000000000000176enlarge_userbuf0000003ab9a756b0lF.text000000000000011bptmalloc_lock_all0000003ab9a757d0lF.text00000000000000b6ptmalloc_unlock_all0000003ab9a75890lF.text00000000000000c1ptmalloc_unlock_all20000003ab9a75960lF.text0000000000000003__failing_morecore0000003ab9a75a20lF.text00000000000000dasYSTRIm0000003ab9a75b00lF.text000000000000029dmem2chunk_check0000003ab9a75da0lF.text00000000000000e0malloc_printerr0000003ab9a75e80lF.text0000000000000541malloc_consolidate0000003ab9a75280lF.text0000000000000187_IO_str_seekoff_internal0000050970F.text000000000000006b__malloc_check_init0000003ab9a75410lF.text00000000000001aa_IO_str_overflow_internal0000003ab9a759e0lF.text0000000000000031__malloc_usable_size0000003ab9a75020lF.text0000000000000062_IO_str_underflow_internal0000003ab9a750b0lF.text000000000000002b_IO_str_finish0000003ab9a75090lF.text0000000000000012_IO_str_count0000003ab9a755c0lF.text00000000000000ae_IO_str_init_static_internal0000003ab9a750e0lF.text0000000000000015_IO_str_pbackfail_internal0000003ab9a759e0wF.文本00000000000031MALLOC_USABLa75670gF.text000000000000001d_IO_str_init_readonly0000003ab9a75690gF.text0000000000000012_IO_str_init_static0000003ab9a75280gF.text0000000000000187_IO_str_seekoff0000003ab9a750e0gDF.text0000000000000015GLIBC_2.2.5_IO_str_pbackfail0000003ab9a75690gDF.text0000000000000012GLIBC_2.2.5_IO_str_init_static0000003ab9a759e0wDF.text0000000000000031GLIBC_2.2.5malloc_usable_size0000003ab9a75020gDF.text0000000000000062GLIBC_2.2.5_IO_str_underflow0000003ab9a75280gDF.text0000000000000187GLIBC_2.2.5_IO_str_seekoff0000003ab9a75410gDF.text00000000000001aaGLIBC_2.2.5_IO_str_overflow0000003ab9a75670gDF.text000000000000001dGLIBC_2.2.5_IO_str_init_readonly为了进一步定位问题点，我们使用objdump命令并指定起始点objdump-d/lib64/libc-2.12.so--start-address=0x3ab9a75000|head-n2000|grep75f62outputisasfollows:3ab9a75ec8:0f8594000000jne3ab9a75f623ab9a75f62:488b4308mov0x8(%rbx),%rax基本可以判断是malloc时出现了问题。上一节我们确定是malloc引起的，但是代码量太大Big，任何对象的底层都可能调用malloc（new也会调用malloc），所以不知道去哪里开始。为了定位原因，使用了最新的定位方法，对上次上线的代码改动进行了分析。这个改动把之前的redisSentinel改成了rediscluster，而redis官方没有提供cluster的client，所以我自己创建了一个client。本客户端调用malloc的顺序为：->Init-->redisClusterInit---->calloc------>malloc好了，至此，进程崩溃的代码点基本定位，以及下面我来分析原因。原因分析程序初始化RedisClusterClient有两个地方：程序启动时断开连接，因为程序运行了一段时间，第一个基本不行，我们看其中一个命令在此更改中使用ZRangeByScore的实现：voidRedisClusterClient::ZRangeByScore(std::string&key,std::stringmin,std::stringmax,std::vector*vals,boolwithscores,std::string*msg){//....redisReply*reply=static_cast(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);}返回;}//...}简单的这一段代码是没有问题的，所以需要考虑这段代码的使用。我们重新梳理了请求的调用链：->Load-->GetHandler---->GetSession------>GetRedisClient重新分析代码，发现在某些情况下，GetRedisClient可能会被多个线程调用同时，如果不执行Init，一切正常，但是当一个线程Init发生时，另一个线程读取，导致访问到一个已经释放的内存地址，从而导致进程崩溃。这种情况发生的概率很低，而且很难重现。毕竟当连接突然断开的时候，另一个线程正在同时访问。还是很难出现在线（当然可以通过tcpkill模拟离线，那另当别论）。一般来说，能够快速定位，已经是相当幸运的事情了。解决问题在整个bug分析和解决过程中，定位segfault是最难的部分。如果知道segfault的位置并分析原因，相对就容易多了。当然，知道了崩溃的原因，解决起来就更简单了