[libvirt-users] "virsh list" hangs

Friday, 17 February 2017

`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(a)sigxcpu.org&gt; 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

-- 
--
Yun-Chih Chen 陳耘志
Network/Workstation Assistant
Dept. of Computer Science and Information Engineering
National Taiwan University
Tel: +886-2-33664888 ext. 217/204
Email: ta217(a)csie.ntu.edu.tw
Website: http://wslab.csie.ntu.edu.tw/

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

[libvirt-users] "virsh list" hangs