`virsh list` hangs on my server that hosts a bunch of VMs.
This might be due to the Debian upgrade I did on Feb 15, which
upgrades `libvirt` from 2.4.0-1 to 3.0.0-2.
I have tried restarting libvirtd for a few times, without luck.
Attached below are some relevant logs; let me know if you need
some more for debugging.
Thanks for your help!!
root@vm-host:~# uname -a
Linux vm-host 4.6.0-1-amd64 #1 SMP Debian 4.6.4-1 (2016-07-18)
x86_64 GNU/Linux
root@vm-host:~# apt-cache policy libvirt-daemon
libvirt-daemon:
Installed: 3.0.0-2
Candidate: 3.0.0-2
Version table:
*** 3.0.0-2 500
500
http://debian.csie.ntu.edu.tw/debian
testing/main amd64 Packages
100 /var/lib/dpkg/status
root@vm-host:~# strace -o /tmp/trace -e trace=network,file,poll
virsh list # hangs forever .....
^C
root@vm-host:~# tail -10 /tmp/trace
access("/etc/libvirt/libvirt.conf", F_OK) = 0
open("/etc/libvirt/libvirt.conf", O_RDONLY) = 5
access("/proc/vz", F_OK) = -1 ENOENT (No such file
or directory)
socket(AF_UNIX, SOCK_STREAM, 0) = 5
connect(5, {sa_family=AF_UNIX,
sun_path="/var/run/libvirt/libvirt-sock"}, 110) = 0
getsockname(5, {sa_family=AF_UNIX}, [128->2]) = 0
poll([{fd=5, events=POLLOUT}, {fd=6, events=POLLIN}], 2, -1) = 1
([{fd=5, revents=POLLOUT}])
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1) = ?
ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
+++ killed by SIGINT +++
root@vm-host:~# lsof /var/run/libvirt/libvirt-sock # hangs too ...
^C
root@vm-host:~# LIBVIRT_DEBUG=1 virsh list
2017-02-17 15:58:36.126+0000: 18505: info : libvirt version:
3.0.0, package: 2 (Guido Günther
<agx@sigxcpu.org> Wed,
25 Jan 2017 07:04:08 +0100)
2017-02-17 15:58:36.126+0000: 18505: info : hostname: vm-host
2017-02-17 15:58:36.126+0000: 18505: debug : virGlobalInit:386 :
register drivers
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:684 : driver=0x7f1e5aca2c40 name=Test
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:695 : registering Test as driver 0
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:684 : driver=0x7f1e5aca4ac0 name=OPENVZ
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:695 : registering OPENVZ as driver 1
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:684 : driver=0x7f1e5aca5260 name=VMWARE
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:695 : registering VMWARE as driver 2
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:684 : driver=0x7f1e5aca3720 name=remote
2017-02-17 15:58:36.127+0000: 18505: debug :
virRegisterConnectDriver:695 : registering remote as driver 3
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventRegisterDefaultImpl:267 : registering default event
implementation
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollAddHandle:115 : Used 0 handle slots, adding at least
10 more
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollInterruptLocked:722 : Skip interrupt, 0 0
2017-02-17 15:58:36.127+0000: 18505: info :
virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=3
events=1 cb=0x7f1e5a7fc140 opaque=(nil) ff=(nil)
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventRegisterImpl:234 : addHandle=0x7f1e5a7fc860
updateHandle=0x7f1e5a7fcb90 removeHandle=0x7f1e5a7fc1a0
addTimeout=0x7f1e5a7fc310 updateTimeout=0x7f1e5a7fc510
removeTimeout=0x7f1e5a7fc6e0
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollAddTimeout:230 : Used 0 timeout slots, adding at least
10 more
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollInterruptLocked:722 : Skip interrupt, 0 0
2017-02-17 15:58:36.127+0000: 18505: info :
virEventPollAddTimeout:253 : EVENT_POLL_ADD_TIMEOUT: timer=1
frequency=-1 cb=0x563a29758360 opaque=0x7fff70941380 ff=(nil)
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenAuth:1245 : name=<null>, auth=0x7f1e5aca2a00,
flags=0
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f5f50 classname=virConnect
2017-02-17 15:58:36.127+0000: 18505: debug :
virConfLoadConfig:1604 : Loading config file
'/etc/libvirt/libvirt.conf'
2017-02-17 15:58:36.127+0000: 18505: debug : virConfReadFile:778 :
filename=/etc/libvirt/libvirt.conf
2017-02-17 15:58:36.127+0000: 18506: debug : virThreadJobSet:99 :
Thread 18506 is now running job vshEventLoop
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventRunDefaultImpl:311 : running default event implementation
2017-02-17 15:58:36.127+0000: 18505: debug : virFileClose:108 :
Closed fd 5
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupTimeouts:525 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupHandles:574 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=3 e=1 d=0
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-02-17 15:58:36.127+0000: 18506: info :
virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=1 timeout=-1
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug : virConfAddEntry:241 :
Add entry (null) (nil)
2017-02-17 15:58:36.127+0000: 18505: debug :
virConfGetValueString:932 : Get value string (nil) 0
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1040 : no name, allowing driver auto-select
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1083 : trying driver 0 (Test) ...
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1098 : driver 0 Test returned DECLINED
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1083 : trying driver 1 (OPENVZ) ...
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1098 : driver 1 OPENVZ returned DECLINED
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1083 : trying driver 2 (VMWARE) ...
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1098 : driver 2 VMWARE returned DECLINED
2017-02-17 15:58:36.127+0000: 18505: debug :
virConnectOpenInternal:1083 : trying driver 3 (remote) ...
2017-02-17 15:58:36.127+0000: 18505: debug :
remoteConnectOpen:1343 : Auto-probe remote URI
2017-02-17 15:58:36.127+0000: 18505: debug : doRemoteOpen:907 :
proceeding with name =
2017-02-17 15:58:36.127+0000: 18505: debug : doRemoteOpen:916 :
Connecting with transport 1
2017-02-17 15:58:36.127+0000: 18505: debug : doRemoteOpen:1051 :
Proceeding with sockname /var/run/libvirt/libvirt-sock
2017-02-17 15:58:36.127+0000: 18505: debug :
virNetSocketNewConnectUNIX:639 :
path=/var/run/libvirt/libvirt-sock spawnDaemon=0
binary=<null>
2017-02-17 15:58:36.127+0000: 18505: debug :
virNetSocketNewConnectUNIX:703 : connect() succeeded
2017-02-17 15:58:36.127+0000: 18505: debug : virNetSocketNew:235 :
localAddr=0x7fff70940d00 remoteAddr=0x7fff70940d90 fd=5 errfd=-1
pid=0
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f7980 classname=virNetSocket
2017-02-17 15:58:36.127+0000: 18505: info : virNetSocketNew:291 :
RPC_SOCKET_NEW: sock=0x563a2a7f7980 fd=5 errfd=-1 pid=0
localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f7d80 classname=virNetClient
2017-02-17 15:58:36.127+0000: 18505: info : virNetClientNew:328 :
RPC_CLIENT_NEW: client=0x563a2a7f7d80 sock=0x563a2a7f7980
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7d80
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7980
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollInterruptLocked:726 : Interrupting
2017-02-17 15:58:36.127+0000: 18505: info :
virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=5
events=1 cb=0x7f1e5a96cd10 opaque=0x563a2a7f7980 ff=0x7f1e5a96ccc0
2017-02-17 15:58:36.127+0000: 18505: debug : virKeepAliveNew:199 :
client=0x563a2a7f7d80, interval=-1, count=0
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f8080 classname=virKeepAlive
2017-02-17 15:58:36.127+0000: 18505: info : virKeepAliveNew:218 :
RPC_KEEPALIVE_NEW: ka=0x563a2a7f8080 client=0x563a2a7f7d80
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7d80
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f6740
classname=virConnectCloseCallbackData
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollRunOnce:650 : Poll got 1 event(s)
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchTimeouts:432 : Dispatch 1
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f6740
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchHandles:478 : Dispatch 1
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f7fa0 classname=virNetClientProgram
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f7b60 classname=virNetClientProgram
2017-02-17 15:58:36.127+0000: 18505: info : virObjectNew:202 :
OBJECT_NEW: obj=0x563a2a7f7910 classname=virNetClientProgram
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchHandles:492 : i=0 w=1
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7fa0
2017-02-17 15:58:36.127+0000: 18506: info :
virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE:
watch=1 events=1
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7b60
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupTimeouts:525 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18505: info : virObjectRef:296 :
OBJECT_REF: obj=0x563a2a7f7910
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupHandles:574 : Cleanup 2
2017-02-17 15:58:36.127+0000: 18505: debug : doRemoteOpen:1170 :
Trying authentication
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventRunDefaultImpl:311 : running default event implementation
2017-02-17 15:58:36.127+0000: 18505: debug : virNetMessageNew:46 :
msg=0x563a2a7fa470 tracked=0
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupTimeouts:525 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupHandles:574 : Cleanup 2
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=3 e=1 d=0
2017-02-17 15:58:36.127+0000: 18505: debug :
virNetMessageEncodePayload:386 : Encode length as 28
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=5 e=1 d=0
2017-02-17 15:58:36.127+0000: 18505: info :
virNetClientSendInternal:2104 : RPC_CLIENT_MSG_TX_QUEUE:
client=0x563a2a7f7d80 len=28 prog=536903814 vers=1 proc=66 type=0
status=0 serial=0
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-02-17 15:58:36.127+0000: 18505: debug :
virNetClientCallNew:2057 : New call 0x563a2a7f7340:
msg=0x563a2a7fa470, expectReply=1, nonBlock=0
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-02-17 15:58:36.127+0000: 18505: debug : virNetClientIO:1866 :
Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0
length=28 dispatch=(nil)
2017-02-17 15:58:36.127+0000: 18506: info :
virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=2 timeout=-1
2017-02-17 15:58:36.127+0000: 18505: debug : virNetClientIO:1925 :
We have the buck head=0x563a2a7f7340 call=0x563a2a7f7340
2017-02-17 15:58:36.127+0000: 18505: info :
virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=2
events=0
2017-02-17 15:58:36.127+0000: 18505: debug :
virEventPollInterruptLocked:726 : Interrupting
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollRunOnce:650 : Poll got 1 event(s)
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchTimeouts:432 : Dispatch 1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchHandles:478 : Dispatch 2
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollDispatchHandles:492 : i=0 w=1
2017-02-17 15:58:36.127+0000: 18506: info :
virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE:
watch=1 events=1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupTimeouts:525 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupHandles:574 : Cleanup 2
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventRunDefaultImpl:311 : running default event implementation
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupTimeouts:525 : Cleanup 1
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollCleanupHandles:574 : Cleanup 2
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=3 e=1 d=0
2017-02-17 15:58:36.127+0000: 18506: debug :
virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=5 e=0 d=0
2017-02-17 15:58:36.128+0000: 18506: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-02-17 15:58:36.128+0000: 18506: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-02-17 15:58:36.128+0000: 18506: info :
virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=1 timeout=-1
^C