最近工作中发现一台虚拟机无法响应管理命令。经过排查，根本原因是 libvirtd 死锁导致。重启libvirtd 后恢复。
现将 debug 过程记录，以后有类似问题可供我们参考。
问题描述：
一台虚拟机手动重启后无法登录虚拟机。登录到物理机准备用 virsh 命令
检查虚拟机，发现virsh 命令 hang。
debug
- 首先用 strace 观察 virsh 函数调用。
# strace virsh
stat("/usr/sbin/libvirtd", {st_mode=S_IFREG|0755, st_size=1491088, ...}) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 6
connect(6, {sa_family=AF_FILE, path="/var/run/libvirt/libvirt-sock"}, 110) = 0
getsockname(6, {sa_family=AF_FILE, NULL}, [2]) = 0
futex(0x36fd238e00, FUTEX_WAKE_PRIVATE, 2147483647) = 0
gettid() = 1630
fcntl(6, F_GETFD) = 0
--- skip ---
gettid() = 1630
write(5, "\0", 1) = 1
futex(0x36fd2382c0, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigprocmask(SIG_BLOCK, [PIPE CHLD WINCH], [], 8) = 0
poll([{fd=6, events=POLLOUT}, {fd=7, events=POLLIN}], 2, -1) = 1 ([{fd=6, revents=POLLOUT}])
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(6, "\0\0\0\34 \0\200\206\0\0\0\1\0\0\0B\0\0\0\0\0\0\0\0\0\0\0\0", 28) = 28
munmap(0x7f3a73bff000, 4198400) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE CHLD WINCH], [], 8) = 0
poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1
可以看到 virsh block 在 poll()， 等待 fd=6 的输入。
fd = 6 是 virsh 与 libvirtd 通信的域套接字fd。 要继续分析 libvird 的状态。
- 用 gdb 调试 libvirtd
libvirtd 是一个正在运行的进程。 使用命令 gdb 调试 libvirtd。
观察线程
# gdb libvird $(pgrep libvirtd)
(gdb) info threads
11 Thread 0x7f84cec7b700 (LWP 21852) 0x000000360800b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
10 Thread 0x7f84ce27a700 (LWP 21853) 0x000000360800edd0 in __pause_nocancel () from /lib64/libpthread.so.0
--- skip ---
2 Thread 0x7f84c9272700 (LWP 21861) 0x000000360800b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1 Thread 0x7f84d4b0d860 (LWP 21851) 0x000000360800e054 in __lll_lock_wait
() from /lib64/libpthread.so.0
可以看到主线程阻塞在锁上。 进一步观察线程栈。
(gdb) t a a bt
Thread 10 (Thread 0x7f84ce27a700 (LWP 21853)):
#0 0x000000360800edd0 in __pause_nocancel () from /lib64/libpthread.so.0
No symbol table info available.
#1 0x0000003608008ffb in __pthread_mutex_lock_full ()
from /lib64/libpthread.so.0
No symbol table info available.
#2 0x000000000048cc82 in ?? ()
No symbol table info available.
#3 0x000000000047dac9 in ?? ()
No symbol table info available.
#4 0x000000000046787e in ?? ()
No symbol table info available.
#5 0x00000036fcef5390 in virDomainDestroy () from /usr/lib64/libvirt.so.0
No symbol table info available.
#6 0x000000000043f892 in ?? ()
No symbol table info available.
---skip---
Thread 1 (Thread 0x7f84d4b0d860 (LWP 21851)):
#0 0x000000360800e054 in __lll_lock_wait () from /lib64/libpthread.so.0
No symbol table info available.
#1 0x0000003608009388 in _L_lock_854 () from /lib64/libpthread.so.0
No symbol table info available.
#2 0x0000003608009257 in pthread_mutex_lock () from /lib64/libpthread.so.0
No symbol table info available.
#3 0x000000000047d6ea in ?? ()
No symbol table info available.
果然，这里发生了死锁， thread10 一直执行 virDomainDestroy(), 没有释放。导致了 libvirtd 主线程
不会响应其他操作。
- 现在问题变成了 virDomainDestroy() 是怎么调用的，为什么没有结束？ 查看 libvirt log，可以看到最近一次 Destroy 命令是三个月前下达的，并且恰好是给这台出问题的虚拟机。
731 2017-03-13 05:10:14.327+000017907: debug : remoteDispatchDomainDestroyHelper:1254 : server=0x18becf0 client=0x18c40b0 msg=0x18c1a80 rerr=0x7fdb57490b80 args=0x7fd b3c010b00 ret=0x7fdb3c003110
732 2017-03-13 05:10:14.327+000017902: debug : virEventPollCleanupTimeouts:501 : Clea nup 3
733 2017-03-13 05:10:14.327+000017902: debug : virEventPollCleanupHandles:549 : Clean up 16
734 2017-03-13 05:10:14.327+000017907: debug : virObjectNew:110 : OBJECT_NEW: obj=0x7 fdb3c002ca0 classname=virDomain
735 2017-03-13 05:10:14.327+000017902: debug : virEventPollMakePollFDs:378 : Prepare n=0 w=1, f=7 e=1 d=0
736 2017-03-13 05:10:14.327+000017907: debug : virObjectRef:168 : OBJECT_REF: obj=0x7 fdb48002180
737 2017-03-13 05:10:14.327+000017902: debug : virEventPollMakePollFDs:378 : Prepare n=1 w=2, f=9 e=1 d=0
738 2017-03-13 05:10:14.327+000017902: debug : virEventPollMakePollFDs:378 : Prepare n=2 w=3, f=12 e=1 d=0
739 2017-03-13 05:10:14.327+000017907: debug : virDomainDestroy:2172 : dom=0x7fdb3c00 2ca0, (VM: name=instance-00000001, uuid=6400025f-5f9b-4409-8053-f0274814cd0a)
接下来 log, 虚拟机 期望进入shutting down 状态：
2017-03-13 05:10:15.928+000017907: debug : qemuProcessStop:4206 : Shutting down VM 'instance-00000001' pid=11004 flags=0
2017-03-13 05:10:15.928+000017907: debug : virFileClose:72 : Closed fd 27
但是接下来，libvirt log记录了一个 end of log
====== end of log =====
按照libvirt 源码， 这种log 是此刻有其他操作同时进行， 为防止log混乱，中断当前log。
查看 qemu log
2017-03-13 05:10:15.928+0000: shutting down
2017-03-13 05:10:51.992+0000: shutting down
2017-03-13 05:11:11.439+0000: starting up
第一个shutting down 是 Destroy 命令做的， 第二个shutting down 未知， 但是这个process 使得 Destroy 动作 永远无法执行下去。
初步结论：
之后没有log表明 destroy 命令是否返回。事实上，该虚拟机3个月来还是正常运转的，并没有被销毁，占用锁的线程一直存在。
所以，可以确定libvirtd 虚拟机 Destroy 命令，会在异常操作下引发死锁。
解决方法：
重启libvirtd，重启虚拟机，系统恢复正常。
