Kissingwolf's Blog

虚拟机故障定位过程

最近一次虚拟机运行故障,记录一下分析思路和过程。

首先是现象,故障事件描述如下:

2017年3月7日15:40左右,业务报告“虚拟机N”上的服务没有响应了,业务运维发现此KVM虚拟机无法登陆,所有通知基础运维并从新启动了这台KVM虚拟机。

虚拟机重启后业务逐步恢复,需要分析KVM无法登陆的原因。

问题分析过程:

  1. 首先登陆虚拟机N和其宿主机H,将其上的/var/log/messages日志文件复制到/tmp/message目录下,分析日志内容。
  2. 在虚拟机N上的messages文件中发现大量干扰日志,格式类似如下内容
1
2
3
4
2017-03-07 03:28:40.240 info watchdog.lnx[16616]: INFO 2017-03-07 03:28:40 watchdog.go:55 Watchdog Sam's alive
2017-03-07 03:28:42.240 info watchdog.lnx[16616]: INFO 2017-03-07 03:28:42 watchdog.go:55 Watchdog Sam's alive
2017-03-07 03:28:44.240 info watchdog.lnx[16616]: INFO 2017-03-07 03:28:44 watchdog.go:55 Watchdog Sam's alive
2017-03-07 03:28:46.240 info watchdog.lnx[16616]: INFO 2017-03-07 03:28:46 watchdog.go:55 Watchdog Sam's alive

所以使用grep将干扰日志项过滤,并显示日志行号方便定位:

1
# cat -nA messages | grep -v watchdog.go |less

发现确切的虚拟机故障时间和重启成功时间,相关内容日志如下:

1
2
3
4
5
18473 2017-03-07 13:30:01.184 info systemd[1]: Removed slice user-0.slice.$
18474 2017-03-07 13:30:01.184 info systemd[1]: Stopping user-0.slice.$
18711 ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@2017-03-07 15:45:26.028 info rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="533" x-info="http://www.rsyslog.com"] start$
18712 2017-03-07 15:45:25.971 err rsyslogd-2181: $WorkDirectory: /var/spool/rsyslog can not be accessed, probably does not exist - directive ignored [try http://www.rsyslog.com/e/2181 ]$
18713 2017-03-07 15:45:26.017 err rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]$

其中空格分割的第一部分为message文件中条目的原始行号。我们为了快速定位问题时间,使用了过滤干扰项,但分析故障时可能还需要查看原始文件,这个原始行号就十分重要了。

  1. 在检查日志虚拟机N日志时,我们定位到了13:37后此虚拟机出现了故障,然后到15:45我们重新启动了这个虚拟机:
1
2
3
4
5
6
7
8
2017-03-07 13:37:52.240 info watchdog.lnx[16616]: INFO 2017-03-07 13:37:52 watchdog.go:55 Watchdog Sam's alive
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@2017-03-07 15:45:26.028 info rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="533" x-info="http://www.rsyslog.com"] start
2017-03-07 15:45:25.971 err rsyslogd-2181: $WorkDirectory: /var/spool/rsyslog can not be accessed, probably does not exist - directive ignored [try http://www.rsyslog.com/e/2181 ]
2017-03-07 15:45:26.017 err rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]

因此,我们需要定位宿主机H上相同时间段,并查看在此时间段内出现和什么故障或报出了什么错误。

我们在H上的message日志文件中发现了同时段报出的错误日志:

1
2
3
4
5
6
Mar 7 13:38:04 H kernel: EPT: Misconfiguration.
Mar 7 13:38:04 H kernel: EPT: GPA: 0x108ba4538
Mar 7 13:38:04 H kernel: ept_misconfig_inspect_spte: spte 0x84c236107 level 4
Mar 7 13:38:04 H kernel: ept_misconfig_inspect_spte: spte 0x10515c7107 level 3
Mar 7 13:38:04 H kernel: ept_misconfig_inspect_spte: spte 0xde4657107 level 2
Mar 7 13:38:04 H kernel: ept_misconfig_inspect_spte: spte 0x1028125d77 level 1

其中关键字段和术语:

字段 含义
EPT Extended Page Table
GPA Guest Physical address

​ 可以看出此错误和KVM虚拟化有关。

​ 进一步查看当时的zstack-agent日志:

1
2
2017-03-07 13:38:04,415 DEBUG [vm_plugin] ignore event[Suspended] of the vm[uuid:2c521dfe81b44151b25ff8e4b852fa4e]
2017-03-07 15:45:08,554 DEBUG [vm_plugin] ignore event[Stopped] for the vm[uuid:2c521dfe81b44151b25ff8e4b852fa4e], this operation is from ZStack itself

发现有虚拟机挂起!

  1. 综上,可以断定是由于虚拟机挂起导致的问题。那么为什么会挂起呢?我们借助google可以查找关键字
1
kernel: EPT: Misconfiguration.

可以找到相关的条目,其中有RedHat 知识库中的条目:

https://access.redhat.com/solutions/1758133

此问题是一个Bug,RedHat知识库描述如下:

Root Cause

A MMIO Page Fault related bug in KVM causes this. This is a Hypervisor side bug and any VM OS might hit it.

The probability of hitting it appears to be quite low (many VMs running for days).

字段 含义
MMIO Memory-mapped I/O

这不是一个常见的错误,RedHat 建议升级内核解决这个Bug:

Resolution