从一个 VNC 黑屏故障谈一谈怎么排查系统层面的问题

上周接到一个用户返回他的云主机操作系统为 centos 7.x,重启后要等很久才可以 SSH 远程连接,通过控制台的 VNC 连接后显示的是整个界面黑屏,屏幕没有输出任何有价值的信息,就是一直黑的

针对这个问题总结一下怎么去排查这个问题。

问题

由于这个是客户的机器,我们是没有权限直接进入系统操作的,因此只能让用户提供 log 信息。通过对/var/log/messages 的日志分析发现 tomcat 停止花了5分钟左右的时间

此外检查了 Tomcat 的 log 发现大量的内存溢出情况

莫名奇妙的好了

后来找用户要了权限对机器进行操作,在/etc/default/grub中去掉了console=ttyS0,115200和rhgb quiet,重新使用“grub2-mkconfig -o /boot/grub2/grub.cfg”重新产生grub,结果修改后,关机慢的现象不会出现了,而且重启恢复了之前的/etc/default/grub,还是无法复现;

奇怪的 rsyslogd日志

另外从用户提供的时间点来看 rsyslogd 服务 在发起 signal 15 信号后也是等了5分钟才启动

这个时间点分别是:

停止15:37:09
启动15:42:23

不过那会查看 Tomcat 的日志可以看出来在15:31就一直包内存溢出到15:31:49 左右停止,15:42:31 启动,又似乎和 Tomcat 没多大关系

我们看下正常的 rsyslogd 的启动和停止,基本几秒就启动了。

   Mar 19 18:14:06 live-linux-kc-403 systemd: Stopping ACPI Event Daemon...
Mar 19 18:14:06 live-linux-kc-403 systemd: Stopping Avahi mDNS/DNS-SD Stack...
Mar 19 18:14:06 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="990" x-info="http://www.rsyslog.com"] exiting on signal 15.
Mar 19 18:14:20 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="1010" x-info="http://www.rsyslog.com"] start
Mar 19 18:14:20 live-linux-kc-403 rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]
Mar 19 18:14:18 live-linux-kc-403 kernel: Initializing cgroup subsys cpuset
Mar 19 18:14:18 live-linux-kc-403 kernel: Initializing cgroup subsys cpu
Mar 19 18:14:18 live-linux-kc-403 kernel: Initializing cgroup subsys cpuacct
Mar 19 18:14:18 live-linux-kc-403 kernel: Linux version 3.10.0-123.el7.x86_64 ([email protected]) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #1 SMP Mon Jun 30 12:09:22 UTC 2014
Mar 19 18:14:18 live-linux-kc-403 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-123.el7.x86_64 root=UUID=59f4da26-a8a2-4950-8101-6c5b9a4688ad ro crashkernel=auto vconsole.font=latarcyrheb-sun16 console=tty0 vconsole.keymap=us console=ttyS0,115200 net.ifnames=0 biosdevname=0 rhgb quiet

另外还有一种情况是,这种看样子是非正常关机,等了2小时才开机

Mar 23 13:54:50 live-linux-kc-403 qemu-ga: info: guest-file-open, handle: 59012
Mar 23 13:54:50 live-linux-kc-403 qemu-ga: info: guest-file-close called, handle: 59012
Mar 23 13:54:50 live-linux-kc-403 qemu-ga: info: guest-file-open called, filepath: /proc/stat, mode: r
Mar 23 13:54:50 live-linux-kc-403 qemu-ga: info: guest-file-open, handle: 59013
Mar 23 13:54:50 live-linux-kc-403 qemu-ga: info: guest-file-close called, handle: 59013
Mar 23 13:54:52 live-linux-kc-403 qemu-ga: info: guest-ping called
Mar 23 13:55:06 live-linux-kc-403 qemu-ga: info: guest-ping called
Mar 23 13:55:07 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="989" x-info="http://www.rsyslog.com"] exiting on signal 15.
Mar 23 15:23:04 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="994" x-info="http://www.rsyslog.com"] start
Mar 23 15:23:04 live-linux-kc-403 rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]
Mar 23 15:23:02 live-linux-kc-403 kernel: Initializing cgroup subsys cpuset
Mar 23 15:23:02 live-linux-kc-403 kernel: Initializing cgroup subsys cpu
Mar 23 15:23:02 live-linux-kc-403 kernel: Initializing cgroup subsys cpuacct
Mar 23 15:23:02 live-linux-kc-403 kernel: Linux version 3.10.0-123.el7.x86_64 ([email protected]) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #1 SMP Mon Jun 30 12:09:22 UTC 2014
Mar 23 15:23:02 live-linux-kc-403 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-123.el7.x86_64 root=UUID=59f4da26-a8a2-4950-8101-6c5b9a4688ad ro crashkernel=auto vconsole.font=latarcyrheb-sun16 console=tty0 vconsole.keymap=us console=ttyS0,115200 net.ifnames=0 biosdevname=0 rhgb quiet
Mar 23 15:23:02 live-linux-kc-403 kernel: e820: BIOS-provided physical RAM map:
Mar 23 15:23:02 live-linux-kc-403 kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
Mar 23 15:23:02 live-linux-kc-403 kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
Mar 23 15:23:02 live-linux-kc-403 kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
Mar 23 15:23:02 live-linux-kc-403 kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000bffdefff] usable

非正常的情况还有

Mar 23 17:02:42 live-linux-kc-403 systemd: Started Session 2 of user root.
Mar 23 17:02:42 live-linux-kc-403 systemd-logind: New session 2 of user root.
Mar 23 17:02:42 live-linux-kc-403 systemd: Starting Session 2 of user root.
Mar 23 17:02:43 live-linux-kc-403 qemu-ga: info: guest-ping called
Mar 23 17:02:45 live-linux-kc-403 systemd: Stopped Dump dmesg to /var/log/dmesg.
Mar 23 17:02:45 live-linux-kc-403 systemd: Stopping Dump dmesg to /var/log/dmesg...
Mar 23 17:02:45 live-linux-kc-403 systemd: Stopped target Timers.
Mar 23 17:02:45 live-linux-kc-403 systemd: Stopping Timers.
Mar 23 17:02:45 live-linux-kc-403 systemd: Stopping Session 2 of user root.
Mar 23 17:02:45 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="1004" x-info="http://www.rsyslog.com"] exiting on signal 15.
Mar 23 17:07:59 live-linux-kc-403 rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="989" x-info="http://www.rsyslog.com"] start
Mar 23 17:07:59 live-linux-kc-403 rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]
Mar 23 17:07:57 live-linux-kc-403 kernel: Initializing cgroup subsys cpuset
Mar 23 17:07:57 live-linux-kc-403 kernel: Initializing cgroup subsys cpu
Mar 23 17:07:57 live-linux-kc-403 kernel: Initializing cgroup subsys cpuacct
Mar 23 17:07:57 live-linux-kc-403 kernel: Linux version 3.10.0-123.el7.x86_64 ([email protected]) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #1 SMP Mon Jun 30 12:09:22 UTC 2014
Mar 23 17:07:57 live-linux-kc-403 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-123.el7.x86_64 root=UUID=59f4da26-a8a2-4950-8101-6c5b9a4688ad ro crashkernel=auto vconsole.font=latarcyrheb-sun16 console=tty0 vconsole.keymap=us console=ttyS0,115200 net.ifnames=0 biosdevname=0 rhgb quiet
Mar 23 17:07:57 live-linux-kc-403 kernel: e820: BIOS-provided physical RAM map:
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000bffdefff] usable
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x00000000bffdf000-0x00000000bfffffff] reserved
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
Mar 23 17:07:57 live-linux-kc-403 kernel: BIOS-e820: [mem 0x0000000100000000-0x000000083fffffff] usable
Mar 23 17:07:57 live-linux-kc-403 kernel: NX (Execute Disable) protection: active

推断

遇到这种问题只有该用户出现过,尚无其他案例,推测:

1.可能和 Tomcat 有关系,因为有大量内存泄露的日志信息;也有可能和 rsyslogd 服务有关系。
2.排查了底层内核、CPU、在堆栈中都没发现异常现象,从云厂商的角度这属于系统层面的问题,应该由用户自行排查服务,比如这种想象是必现的可以看下关机前的资源利用率,看看是不是哪个进程占用资源高;在比如可以用排除法先取消 Tomcat 自启动后再尝试看看是否还会出现类似问题;另外可以谷歌搜下看看相关报错或根据关键词,例如 centos 7 重启卡住,我就查找到类似结果,例如:

Tomcat 7/8都使用org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom类产生安全随机类SecureRandom的实例作为会话ID,这里花去了342秒,也即接近6分钟。参考这里

如果关机特别慢(甚至跟死机了一样),很可能是某个拒不退出的服务在作怪。systemd 会等待一段时间,然后再尝试杀死它。请阅读这篇文章,确认你是否是该问题受害者。

因为 rsyslogd 发送的信号是15,等于 kill -15 rsyslogdpid 而除了kill 除了 -9 是强制杀死进程的,其他都是有条件忽略的。比如上文中就说了:

Just like with boot problems, when you encounter a hang during shutting down, make sure you wait at least 5 minutes to distinguish a permanent hang from a broken service that's just timing out. 

所以这种系统进程的问题实在不是那么好排查,如实在无法解则迁移服务重装系统。毕竟这个只是影响关机时间,对服务没有影响。

从本问题来看影响的只是开机时间,对于系统内的服务影响基本没有。而该用户一直在和我们钻牛角尖说影响了他们的项目进度,没了这台服务器项目就无法进行了,其实我觉得这就是借口,希望把问题推到云服务商,为什么这么说:

1.首先,一个高可用的服务绝对不能出现单点故障,难道一天没解决,你项目就拖一天,不想其他办法解决了?况且我们对于云主机是有第三方说明的,哪些层面是我们可以排查和处理以及能负责的,哪些是用户自己排查和处理的,现在这个问题我们已经给出方向了是系统进程,可能是 Tomcat 也可能是 syslogd 服务有异常导致的问题。

2.此外在出现问题之前该用户根本就没想到去排查系统层面的日志和服务而是直接找我们处理,而到了我们给他们提供日志证明可能和 Tomcat 或 syslogd 服务 有关系时就开始拿一堆日志证明我们的推论是错误的。

3.该用户以往的故障申报情况看运维水平比较一般,设置自动挂载磁盘后卸载磁盘出现问题这种简单的错误都不知道怎么处理。

写在最后

云厂商出售的只是硬件资源和网络资源,用户的业务场景使用系统千变万化,我们在出现问题时根本不知道用户在系统层面做了哪些操作,修改了哪些文件,改了哪些内核参数。这些未知的因素都会影响排查问题的准确性。因此没有任何一家云厂商敢做出承诺提用户进行运维故障排查操作。

就比如阿里云这样的大厂也不承诺同时也没有能力对于自己的所有用户的系统做代运维操作。如果有这能力,那千千万万的运维人员估计都要失业了吧!