问题描述
最近处理一现场反馈时,有遇到关机变重启的问题。现象是执行关机命令,但是却因为某种原因变为了重启,复现的概率非常大。
问题初步定位过程
最开始的怀疑方向在软件层面,做了如下尝试:
- 使用其它的关机命令
无效 - 使用关机命令的不同参数
无效 - 使用 sysrq 的关机命令
sysrq 关机可以执行如下命令,经过确认现场的设备内核配置未开启 sysrq-trigger 功能。
echo 1 > /proc/sys/kernel/sysrq; echo o > /proc/sysrq-trigger
- 尝试自己编写程序调用 reboot 系统调用关机
这是我在阅读关机操作相关的系统调用后提出的一个方案,实际上与通过 sysrq 关机方式的过程大致相同。同样无效! - 更换设备
新更换的设备也能够复现相同的问题! - 尝试更换机器的系统测试
更换其它产品的系统,发现能够正常关机!
扩大信息以解决问题
在初步定位过程中,更换其它系统后能够正常关机,能够大概率排除硬件问题,猜测可能是在关机的过程中出现了某种异常导致了问题。
要验证这一点也非常简单,给设备接上串口,继续关机查看串口输出也许能够看出一些端倪。可是测试的时候却发现串口没有内核相关的打印内容,这不太合理。
首先查看系统中的 printk 打印级别,内容如下:
$ cat /proc/sys/kernel/printk
0 4 0 0
看到这个输出信息有点惊讶,console_level 竟然被设置为 0,怪不得串口没有内核相关的打印信息呢。
于是首先在产品的关机流程中添加如下命令降低打印机别:
echo "7 4 7 4" > /proc/sys/kernel/printk
修改完成后继续关机,复现问题后查看串口信息发现了如下信息:
这个内核堆栈信息表明 eth0 发包超时,内核 oops 了,猜测这个问题可能就是关机变重启的关键所在。
对这个问题进行分析,应该是在 acpi 切换了电源状态时,eth0 还在发包,而此时由于电源状态的改变,硬件已经不能处理了,就导致发包超时,内核 crash,进而导致看门狗重启系统。
如何解决问题
上文中描述的 eth0 发包超时内核 oops 的问题之前有遇到过,不过却是在开机时产生的。在这个问题出现后接口便一直无法发包,规避方案是执行一次 down、up。
在这个场景中,问题是在关机的时候出现的,与我之前遇到的情况有所区别。不过从 dmesg 信息看,真正的问题应该是为什么 acpi 切换电源状态的时候 eth0 还在收发包?
这个问题其实跟我们定制化的系统有关系,我们的系统并不像常见的发行版那样通过 network-manager、networking 这些服务来管理网络,也不会在关机的时候通过这些服务来关闭网络,这才是真正的问题所在!
于是我在产品的关机流程中添加了如下命令:
awk -F: '/:/{ print $1 }' /proc/net/dev | xargs -i ifconfig '{}' down
这一命令将会 down 掉所有的网络接口,接口 down 掉后自然也就不会再发包了,测试确定问题得到解决!
正常关机时的 dmesg 信息
写这篇文章的时候,我发现在这个问题的定位过程我们忽略了一个非常重要的信息,这个信息就是正常关机时的 dmesg 信息。
正常关机时的 dmesg 信息贴到下面:
[ 186.343205] ixgbe 0000:09:00.1: PCI INT B disabled
[ 186.359127] ixgbe 0000:09:00.0: PCI INT C disabled
[ 186.375103] ixgbe 0000:05:00.1: PCI INT B disabled
[ 186.390073] ixgbe 0000:05:00.0: PCI INT C disabled
[ 186.419584] igb 0000:04:00.3: PCI INT D disabled
[ 186.434757] igb 0000:04:00.3: Refused to change power state, currently in D0
[ 186.455482] igb 0000:04:00.2: PCI INT C disabled
[ 186.470654] igb 0000:04:00.2: Refused to change power state, currently in D0
[ 186.491379] igb 0000:04:00.1: PCI INT B disabled
[ 186.506551] igb 0000:04:00.1: Refused to change power state, currently in D0
[ 186.527276] igb 0000:04:00.0: PCI INT A disabled
[ 186.542482] igb 0000:04:00.0: Refused to change power state, currently in D0
[ 186.549569] ehci_hcd 0000:00:1d.0: PCI INT A disabled
[ 186.554628] ehci_hcd 0000:00:1a.0: PCI INT A disabled
[ 186.559707] ACPI: Preparing to enter system sleep state S5
[ 186.565669] Disabling non-boot CPUs ...
[ 186.686212] Power down.
倒数三行信息挺关键,从 ACPI 切换系统电源状态到 S5,再到关闭所有的非引导 cpu,最后打印 Power down 表示关机完成,本文描述的问题中,Power down 这一行就没有打印,替代的内容就是 eth0 发包超时的内核堆栈信息。
上面贴出的信息中另外一个可能存在问题的点是 igb 的几个接口拒绝切换电源状态,仍旧保持 D0 这一完全运行状态,也许跟 bypass 有些关系,不进一步深究了!
总结
从本文中的描述中可以看出这个问题并不太难,甚至于仅仅只修改了一行代码就解决了问题,但在此之前已经花了两周左右的时间。
一开始产品找我看的时候也只提供了关机脚本的打印信息,问题前期定位完全没有关注到 dmesg 的打印信息,当补上了 dmesg 的信息后,真正的问题才浮出了水面。
最后不得不提的是基线数据,在这个问题中,oops 的内容指向性很强,有没有基线数据在这个问题中无足轻重。可如果问题不这么明显,这时候基线数据就变得非常重要了,缺少这个数据问题就变得不那么容易解决了!我们应该有意识的收集基线数据,它也是我们能够从一个个问题中挖掘出的价值所在!