一、概述
众所周知,从事linux内核开发的工程师或多或少都会遇到内核panic,亦或者是soft lockup,前者多半是因为内存泄露、内存互踩、访问空地址等错误导致的,而后者可以肯定是因为代码的逻辑不当,进而导致内核进入一个死循环。问题可大可小,当问题足够隐蔽又难以复现时通常会让程序猿们十分抓狂,我前些日子有幸体验了一把,足足花费了我一周时间才成功找到问题,为了让自己以后能从容的面对内核panic,也为了能积累更多的经验,还是用文字记录下来才是最好的形式。
提到内核panic就不得不提kdump,这是对付内核panic的利器,kdump实际上是一个工具集,包括一个带有调试信息的内核镜像(捕获内核),以及kexec、kdump、crash三个部分,kdump本质上是一个内核崩溃转储工具,即在内核崩溃时捕获尽量多的信息生成内核core文件。工作原理如下:
(1) kexec分为内核态的kexec_load和用户态的kexec-tools,系统启动时将原内核加载到内存中,kexec_load将捕获内核也一起加载到内存中,加载地址可在grub.conf中配置,默认为auto,kexec-tools则将捕获内核的加载地址传给原内核;
(2) 原内核系统崩溃的触发点设置在die()、die_nmi()、panic(),前两者最终都会调用panic(),发生崩溃时dump出进程信息、函数栈、寄存器、日志等信息,并使用ELF文件格式编码保存在内存中,调用machine_kexec(addr)启动捕获内核,捕获内核最终转储core文件。捕获内核通常可以采用两种方式访问原内核的内存信息,一种是/dev/oldmem,另一种则是/proc/vmcore;
(3) crash工具提供一些调试命令,可以查看函数栈,寄存器,以及内存信息等,这也是分析问题的关键,下面列举几个常用命令。
log:显示日志;
bt:加参数-a时显示各任务栈信息;
sym:显示虚拟地址对应的标志符,或相反;
ps:显示进程信息;
dis:反汇编函数或者虚拟地址,通过与代码对比,结合寄存器地址找出出错代码中相关变量的地址;
kmem:显示内存地址对应的内容,或slab节点的信息,若出错地方涉及slab,通过kmem则可看到slab的分配释放情况;
rd:显示指定内存的内容;
struct:显示虚拟地址对应的结构体内容,-o参数显示结构体各成员的偏移;
下面借用一下别人画的内核panic流程框图:
通常内核soft lockup问题不会导致内核崩溃,只有设置softlockup_panic才会触发panic,所以若未设置可在崩溃前自行查看系统日志查找原因,如果查找不出原因,再借助人为panic转储core文件,这时通过crash分析问题。
linux中借助看门狗来检测soft lockup问题,每个cpu对应一个看门狗进程,当进程出现死锁或者进入死循环时看门狗进程则得不到调度,系统检测到某进程占用cpu超过20秒时会强制打印soft lockup警告,警告中包含占用时长和进程名及pid。
linux内核设置不同错误来触发panic,其触发选项均在/proc/sysy/kernel目录下,包含sysrq、softlockup_panic、panic、panic_on_io_nmi、panic_on_io_nmi、panic_on_oops、panic_on_unrecovered_nmi、unknown_nmi_panic等。
二、panic实例分析
涉及的代码是处理DNS请求,在DNS请求中需要对重复出现的域名进行压缩,以达到节约带宽的目的,压缩的思想很简单,采用最长匹配算法,偏移量基于DNS头地址。系统中每个cpu维护一个偏移链表,每次处理一个域名前都会到链表中查询这个域名是否已经处理过,若处理过这时会使用一个偏移值。
例如:www.baidu.com,链表中会存储www.baidu.com、baidu.com、com三个节点,之后每次查询链表时若查到则使用节点中的偏移,若未查到则将新出现的域名按照这个规律加到链表中。
这里贴出基本的数据结构:
struct data_buf {
unsigned char* buf;
u16 buflen;
u16 pos;
};
struct dns_buf {
struct data_buf databuf;
struct sk_buff* skb;
u32 cpuid;
};
代码中静态分配了50个节点,每处理一个域名时取一个节点挂入链表中,每次panic都发生在查询节点函数get_offset_map(data_buf *dbuf, char *domain)的list_for_each()中。因此,猜测其可能是由于遍历到空指针或非法地址导致的,原因应该是由于内存溢出导致的内存互踩,每次panic都是发生在晚上,一般会发生几次。
起初的办法是在函数中加入判断条件来调用BUG_ON()函数来提前触发panic,通过验证发现有时会出现list_head节点地址为空,有时会出现遍历节点数超过50次,用反汇编dis命令打印出错节点的地址,最终也只看出了某个节点为空,不过对第二种情况有了一些猜测,压缩时所指向的域名可能出现了问题,在这个函数中徘徊了很久都没有定论,最终得出结论:单纯从这个函数入手是不可能找到原因的,只有打印出原始请求信息和响应信息才能进一步分析,但这个函数所传入的信息很有限,最后只能把所有信息都存储在data_buf这个结构体中,这是我能想到的最直接也是代码改动最小的办法,随着问题的深入这个结构体已经达到了几十个变量,甚至超过了2k大小,也就是超过了函数栈的大小。问题向上追溯到了pskb_expand_head()函数,在这个函数之前打印原始的skb内容,之后打印当前处理的skb内容,发现两次skb的内容不同,当时就误认为问题出在pskb_expand_head()函数上,下面贴出当时的分析报告:
从目前分析是因为收到请求包中的edns选项部分数据不正确,并包含大量垃圾数据,这些请求通常来自巴西(200.13.144.4),当请求累积到一定数量时可能就会导致死机,定位到出错代码位于expand_dnsbuf()中,这个函数中又调用了pskb_expand_head()函数,初步推测问题出在pskb_expand_head()函数中。
出错现象表现为扩展前的SKB数据正确,而扩展后SKB数据已经改变,如原始数据包长度为500(长度不定,240~500不等,正常请求不应该为这么长),请求中dnsid为0x7ebf,问题区和附加区计数均为1,请求域名为lbs.moji.com,扩展后dnsid仍为0x7ebf,问题区仍为1,附加区则变为0,请求域名则变为zj.dcys.ksmobile.com,也就是可能另一个正常请求(不带edns)覆盖了当前(带edns,并包含大师垃圾数据)的dnsbuf,但DNSID却未被覆盖,同时覆盖的域名都比原始域名长,当查询到答案后putwired请求域名,此时原域名的'\0'被覆盖,在压缩请求域名时检测不到'\0',因此导致offset数组溢出或者地址错误,最终死在get_offset_map()函数中。
两次skb内容对比如下:
红框中依次为dnsid,附加区数量,请求域名('\0'),pos为当前要写的位置,很显然'\0'已被覆盖,pos之后为edns选项,00 29正确,表示edns选项,10 00表示负载长度4096,80 00为Z标志,一般为0,之后是edns长度,这里为0,一般为11或者12,所以由此看来edns选项数据不正确,之后还有很多垃圾数据。
其它问题:在本机进行构造这种数据包时并未导致服务器死机,有时有回应,有时则无回应,但回应的数据包依然存在错误,有时是权威区中域名被更改,有时附加段的edns出现在了应答区或者权威区,如下图:
根本原因:因为这是偶然现象,并且当请求量特别大时才可能出现,在不死机的情况下很难打印信息,所以目前并未找到根本原因。
解决办法:对这种请求可以校验edns选项的合法性以及检验数据长度,如出现这种数据包直接丢掉;或将请求域名存入数组中,必要时可以在回应响应包时从DNS头部重写数据,但不知此种办法是否会导致其它内存错误。
当时基本上已经快放弃了,刚开始以为这是因为内存互踩导致的,所以现象应该不好复现,不过后来通过发送大量带有垃圾数据的请求已经能够复现了,可见这不是偶尔现象,而是必然现象。当时一直认为是内存被修改,而没有考虑地址的指向是否错误,因为响应时数据是部分出错,而dnsid,问题区的域名只有读的操作却没有写的操作,最大的迷惑是未找到内存是在何处被修改的,所以猜测应该是在扩展skb函数中数据拷贝后被修改的,没有办法只能把内核中的pskb_expand_head()函数搬到模块中,在这个函数中排错,结果意外的发现,拷贝一直到退出这个函数后数据都没有改变,接着又迷惑了。再后来无意中打印原始的dnsbuf地址,发现其与扩展前的ip头地址相差很大,这时才发现dnsbuf的地址可能在某处被修改了,经过不断的复现现象,最终定位在skb_linearize()函数中,真是突然之间柳暗花明,问题的根本原因是因为skb线性化函数使用后没有更改地址导致的。
在skb_linearize()函数中
1)如果是正常请求,一般head到end之间的线性空间就够用,并且大多也不存在分片的情况,线性化后线性化地址和内存空间保护不变;
2)如果请求中带有大量垃圾数据,那么线性空间通常会不够用,并且存在分片内容,此时在线性化函数中会重新分配线性空间。
第二种即为异常情况,此时skb中head,data,iph等指针已发生变化,而原代码中一直在使用已经被释放的地址,若被释放的地址没被重新分配,此时返回的可能是部分出错的响应包,当收到大量这种请求包时系统通常会死机。
具体代码如下:
在代码中加入iph = ip_hdr(skb);这行代码即可解决问题,小小的一行代码害苦了好多人,当然我是受伤最重的,在这里要牢记skb线性化后一定要重新获取ip头。
总结:排错经验就是crash vmcore镜像+猜测原因+多加打印信息+想办法重现现象。先从导致内核崩溃的代码入手,因为是线上环境导致的,所以很难测试,因此一定要猜测哪些因素导致的,选择好要打印的信息,并想办法传入最终崩溃的函数中,在崩溃的函数中加入判断崩溃的条件,打印完信息后调用BUG_ON()让系统崩溃生成crash文件。本来已经到了分析的瓶颈了,因为之前一直以为skb内存地址在某处被修改,并一度以为是在pskb_expand_head()处导致的,后来还把内核中的函数搬到模块中,以便输出信息,沿着这条路最终发现是一条死路,之后只能从skb中各指针的地址,以及dnsbuf的地址,ip头的地址开始排查,终于发现是ip头的地址发生了改变,最终才找到问题的根本原因。另一个最大的感受就是一定要想办法复现现象,因为线上的环境很复杂,而且这个现象是偶尔现象,每天都是晚上才发生两三次,这也导致问题更加难解决,最终通过构造这种数据包,并大量的发送给服务器才复现了现象。
三、soft lockup实例
同事最近遇到一个soft lockup问题,他就借助了dis反汇编,并与原代码进行对比
从汇编中看出出错的节点地址存在r10寄存器中,r10的地址为88085076de40,接着借助struct命令查看结构体中成员的赋值情况
到这里发现了原来是在遍历链表时遍历到某个节点时它的前驱和后继都指向自己,因此发生了死循环,顺着代码的流程发现,原来是这个节点执行了两次list_add_tail(),问题迎刃而解。
这个案例相对上面那个panic案例的情况要简单一些,出错的问题是围绕着链表的操作,最后发现是代码的逻辑问题,相对来说问题不那么隐蔽。通过这两个案例我学到了不少排错经验,有一个清晰的排错思路很关键,否则在烦躁中很难定位出问题的所在。