852490 – libvirt client (F18, non-root) hangs in virNetClientIOEventLoop

Bug 852490 - libvirt client (F18, non-root) hangs in virNetClientIOEventLoop

Summary: libvirt client (F18, non-root) hangs in virNetClientIOEventLoop

Keywords:
Status:	CLOSED DUPLICATE of bug 877110
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	libvirt
Sub Component:
Version:	18
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Libvirt Maintainers
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2012-08-28 17:13 UTC by Richard W.M. Jones
Modified:	2013-01-27 21:19 UTC (History)
CC List:	10 users (show)
Fixed In Version:
Clone Of:
Environment:
Last Closed:	2013-01-27 21:19:50 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Description Richard W.M. Jones 2012-08-28 17:13:03 UTC

Description of problem:

(Some similarities to bug 821468)

Very simple, do this as *non root*:

  gdb --args virsh list

It will hang.  After some time, hit ^C and get a stack trace:

(gdb) info threads
  Id   Target Id         Frame 
  2    Thread 0x7ffff19c1700 (LWP 20765) "virsh" 0x00000030d0ae8e8d in poll ()
   from /lib64/libc.so.6
* 1    Thread 0x7ffff7fc6840 (LWP 20762) "virsh" 0x00000030d0ae8e8d in poll ()
   from /lib64/libc.so.6
(gdb) bt
#0  0x00000030d0ae8e8d in poll () from /lib64/libc.so.6
#1  0x0000003b84f372b1 in poll (__timeout=-1, __nfds=2, __fds=0x7fffffffd6a0)
    at /usr/include/bits/poll2.h:46
#2  virNetClientIOEventLoop (client=client@entry=0x66ee50, 
    thiscall=thiscall@entry=0x66ebb0) at rpc/virnetclient.c:1390
#3  0x0000003b84f379e8 in virNetClientIO (thiscall=0x66ebb0, client=0x66ee50)
    at rpc/virnetclient.c:1662
#4  virNetClientSendInternal (client=client@entry=0x66ee50, 
    msg=msg@entry=0x66efe0, expectReply=expectReply@entry=true, 
    nonBlock=nonBlock@entry=false) at rpc/virnetclient.c:1835
#5  0x0000003b84f38b8b in virNetClientSendWithReply (
    client=client@entry=0x66ee50, msg=msg@entry=0x66efe0)
    at rpc/virnetclient.c:1863
#6  0x0000003b84f39338 in virNetClientProgramCall (prog=prog@entry=0x66efb0, 
    client=client@entry=0x66ee50, serial=serial@entry=0, proc=proc@entry=66, 
    noutfds=noutfds@entry=0, outfds=outfds@entry=0x0, ninfds=ninfds@entry=0x0, 
    infds=infds@entry=0x0, 
    args_filter=args_filter@entry=0x30d0b25590 <xdr_void>, args=0x0, 
    ret_filter=0x3b84f32670 <xdr_remote_auth_list_ret>, 
    ret=ret@entry=0x7fffffffdb30) at rpc/virnetclientprogram.c:327
#7  0x0000003b84f1ae38 in callWithFD (ret=0x7fffffffdb30 "", 
    ret_filter=<optimized out>, args=<optimized out>, 
    args_filter=0x30d0b25590 <xdr_void>, proc_nr=66, fd=-1, 
    flags=<optimized out>, priv=0x66e730, conn=<optimized out>)
    at remote/remote_driver.c:4873
#8  call (priv=priv@entry=0x66e730, flags=flags@entry=0, 
    proc_nr=proc_nr@entry=66, args_filter=0x30d0b25590 <xdr_void>, 
    args=args@entry=0x0, ret_filter=<optimized out>, 
    ret=ret@entry=0x7fffffffdb30 "", conn=<optimized out>)
    at remote/remote_driver.c:4894
#9  0x0000003b84f2c327 in remoteAuthenticate (authtype=0x0, 
    auth=0x3b852d3de0 <virConnectAuthDefault>, priv=0x66e730, conn=0x66d3a0)
    at remote/remote_driver.c:2802
#10 doRemoteOpen (conn=conn@entry=0x66d3a0, priv=priv@entry=0x66e730, 
    auth=auth@entry=0x3b852d3de0 <virConnectAuthDefault>, flags=flags@entry=6)
    at remote/remote_driver.c:720
#11 0x0000003b84f2e0a0 in remoteOpen (conn=0x66d3a0, 
    auth=0x3b852d3de0 <virConnectAuthDefault>, flags=<optimized out>)
    at remote/remote_driver.c:912
#12 0x0000003b84edf39d in do_open (name=name@entry=0x0, 
    auth=auth@entry=0x3b852d3de0 <virConnectAuthDefault>, flags=flags@entry=0)
    at libvirt.c:1178
#13 0x0000003b84ee11f9 in virConnectOpenAuth (name=0x0, 
    auth=0x3b852d3de0 <virConnectAuthDefault>, flags=0) at libvirt.c:1407
#14 0x000000000040e04b in vshReconnect (ctl=ctl@entry=0x7fffffffe0f0)
    at virsh.c:614
#15 0x000000000040e218 in vshCommandRun (ctl=ctl@entry=0x7fffffffe0f0, 
    cmd=0x66bbe0) at virsh.c:1872
#16 0x000000000040b4d0 in main (argc=<optimized out>, argv=0x7fffffffe2a8)
    at virsh.c:3282
(gdb) thread 2
[Switching to thread 2 (Thread 0x7ffff19c1700 (LWP 20765))]
#0  0x00000030d0ae8e8d in poll () from /lib64/libc.so.6
(gdb) bt
#0  0x00000030d0ae8e8d in poll () from /lib64/libc.so.6
#1  0x0000003b84e5b1ab in poll (__timeout=-1, __nfds=1, __fds=<optimized out>)
    at /usr/include/bits/poll2.h:46
#2  virEventPollRunOnce () at util/event_poll.c:615
#3  0x0000003b84e59f37 in virEventRunDefaultImpl () at util/event.c:247
#4  0x000000000040e8d3 in vshEventLoop (opaque=opaque@entry=0x7fffffffe0f0)
    at virsh.c:2416
#5  0x0000003b84e6abf9 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#6  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#7  0x00000030d0af196d in clone () from /lib64/libc.so.6


Version-Release number of selected component (if applicable):

libvirt-0.10.0-0rc0.2.fc18.x86_64

How reproducible:

100%

Comment 1 Richard W.M. Jones 2012-08-28 17:15:34 UTC

LIBVIRT_DEBUG output:

2012-08-28 17:14:56.023+0000: 9979: info : libvirt version: 0.10.0, package: 0rc0.2.fc18 (Fedora Project, 2012-08-14-15:36:22, )
2012-08-28 17:14:56.023+0000: 9979: debug : virInitialize:424 : register drivers
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d3e60 name=Test
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterDriver:747 : registering Test as driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterNetworkDriver:564 : registering Test as network driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterInterfaceDriver:594 : registering Test as interface driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterStorageDriver:624 : registering Test as storage driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterDeviceMonitor:654 : registering Test as device driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterSecretDriver:684 : registering Test as secret driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterNWFilterDriver:714 : registering Test as network filter driver 0
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d5a60 name=OPENVZ
2012-08-28 17:14:56.023+0000: 9979: debug : virRegisterDriver:747 : registering OPENVZ as driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d5fc0 name=VMWARE
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:747 : registering VMWARE as driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d5300 name=PHYP
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:747 : registering PHYP as driver 3
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterStorageDriver:624 : registering PHYP as storage driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterInterfaceDriver:594 : registering PHYP as interface driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : vboxRegister:133 : VBoxCGlueInit failed, using dummy driver
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d6520 name=VBOX
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:747 : registering VBOX as driver 4
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterNetworkDriver:564 : registering VBOX as network driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterStorageDriver:624 : registering VBOX as storage driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d96c0 name=ESX
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:747 : registering ESX as driver 5
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterInterfaceDriver:594 : registering ESX as interface driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterNetworkDriver:564 : registering ESX as network driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterStorageDriver:624 : registering ESX as storage driver 3
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDeviceMonitor:654 : registering ESX as device driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterSecretDriver:684 : registering ESX as secret driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterNWFilterDriver:714 : registering ESX as network filter driver 1
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d9fe0 name=Hyper-V
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDriver:747 : registering Hyper-V as driver 6
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterInterfaceDriver:594 : registering Hyper-V as interface driver 3
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterNetworkDriver:564 : registering Hyper-V as network driver 3
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterStorageDriver:624 : registering Hyper-V as storage driver 4
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterDeviceMonitor:654 : registering Hyper-V as device driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterSecretDriver:684 : registering Hyper-V as secret driver 2
2012-08-28 17:14:56.024+0000: 9979: debug : virRegisterNWFilterDriver:714 : registering Hyper-V as network filter driver 2
2012-08-28 17:14:56.025+0000: 9979: debug : parallelsRegister:1722 : Can't find prlctl command in the PATH env
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterDriver:732 : driver=0x3b852d4780 name=remote
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterDriver:747 : registering remote as driver 7
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterNetworkDriver:564 : registering remote as network driver 4
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterInterfaceDriver:594 : registering remote as interface driver 4
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterStorageDriver:624 : registering remote as storage driver 5
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterDeviceMonitor:654 : registering remote as device driver 3
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterSecretDriver:684 : registering remote as secret driver 3
2012-08-28 17:14:56.025+0000: 9979: debug : virRegisterNWFilterDriver:714 : registering remote as network filter driver 3
2012-08-28 17:14:56.025+0000: 9979: debug : virEventRegisterDefaultImpl:204 : registering default event implementation
2012-08-28 17:14:56.025+0000: 9979: debug : virEventPollAddHandle:111 : Used 0 handle slots, adding at least 10 more
2012-08-28 17:14:56.025+0000: 9979: debug : virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2012-08-28 17:14:56.025+0000: 9979: debug : virEventPollAddHandle:136 : EVENT_POLL_ADD_HANDLE: watch=1 fd=4 events=1 cb=0x3b84e5a010 opaque=(nil) ff=(nil)
2012-08-28 17:14:56.025+0000: 9979: debug : virEventRegisterImpl:177 : addHandle=0x3b84e5ab20 updateHandle=0x3b84e5aa10 removeHandle=0x3b84e5a430 addTimeout=0x3b84e5a590 updateTimeout=0x3b84e5a760 removeTimeout=0x3b84e5a890
2012-08-28 17:14:56.025+0000: 9979: debug : virConnectOpenAuth:1406 : name=(null), auth=0x3b852d3de0, flags=0
2012-08-28 17:14:56.025+0000: 9980: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollCleanupTimeouts:501 : Cleanup 0
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used, releasing 0
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollCleanupHandles:549 : Cleanup 1
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollMakePollFDs:378 : Prepare n=0 w=1, f=4 e=1 d=0
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollCalculateTimeout:320 : Calculate expiry of 0 timers
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollCalculateTimeout:346 : Timeout at 0 due in -1 ms
2012-08-28 17:14:56.025+0000: 9980: debug : virEventPollRunOnce:614 : EVENT_POLL_RUN: nhandles=1 timeout=-1
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1134 : no name, allowing driver auto-select
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 0 (Test) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 0 Test returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 1 (OPENVZ) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 1 OPENVZ returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 2 (VMWARE) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 2 VMWARE returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 3 (PHYP) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 3 PHYP returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 4 (VBOX) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 4 VBOX returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 5 (ESX) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 5 ESX returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 6 (Hyper-V) ...
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1183 : driver 6 Hyper-V returned DECLINED
2012-08-28 17:14:56.026+0000: 9979: debug : do_open:1177 : trying driver 7 (remote) ...
2012-08-28 17:14:56.026+0000: 9979: debug : remoteOpen:900 : Auto-probe remote URI
2012-08-28 17:14:56.026+0000: 9979: debug : remoteOpen:903 : Auto-spawn user daemon instance
2012-08-28 17:14:56.026+0000: 9979: debug : doRemoteOpen:572 : proceeding with name = 
2012-08-28 17:14:56.026+0000: 9979: debug : doRemoteOpen:582 : Connecting with transport 1
2012-08-28 17:14:56.026+0000: 9979: debug : doRemoteOpen:629 : Proceeding with sockname /run/user/1000/libvirt/libvirt-sock
2012-08-28 17:14:56.027+0000: 9979: debug : virNetSocketNew:119 : localAddr=0x7fffc0431e20 remoteAddr=0x7fffc0431eb0 fd=6 errfd=-1 pid=0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetSocketNew:179 : RPC_SOCKET_NEW: sock=0x2111c90 refs=1 fd=6 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetSocketRef:713 : RPC_SOCKET_REF: sock=0x2111c90 refs=2
2012-08-28 17:14:56.027+0000: 9979: debug : virEventPollInterruptLocked:701 : Interrupting
2012-08-28 17:14:56.027+0000: 9979: debug : virEventPollAddHandle:136 : EVENT_POLL_ADD_HANDLE: watch=2 fd=6 events=1 cb=0x3b84f43690 opaque=0x2111c90 ff=0x3b84f43d20
2012-08-28 17:14:56.027+0000: 9979: debug : virKeepAliveNew:203 : client=0x2111f90, interval=-1, count=0
2012-08-28 17:14:56.027+0000: 9979: debug : virKeepAliveNew:227 : RPC_KEEPALIVE_NEW: ka=0x2111f10 client=0x2111f90 refs=1
2012-08-28 17:14:56.027+0000: 9979: debug : virNetClientNew:354 : RPC_CLIENT_NEW: client=0x2111f90 refs=3 sock=0x2111c90
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollRunOnce:625 : Poll got 1 event(s)
2012-08-28 17:14:56.027+0000: 9979: debug : doRemoteOpen:719 : Trying authentication
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollDispatchTimeouts:410 : Dispatch 0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetMessageNew:45 : msg=0x21120b0 tracked=0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollDispatchHandles:455 : Dispatch 1
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollDispatchHandles:469 : i=0 w=1
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollDispatchHandles:483 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2012-08-28 17:14:56.027+0000: 9979: debug : virNetMessageEncodePayload:358 : Encode length as 28
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupTimeouts:501 : Cleanup 0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetClientSendInternal:1821 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2111f90 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetClientCallNew:1774 : New call 0x21106b0: msg=0x21120b0, expectReply=1, nonBlock=0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used, releasing 0
2012-08-28 17:14:56.027+0000: 9979: debug : virNetClientIO:1584 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil)
2012-08-28 17:14:56.027+0000: 9979: debug : virNetClientIO:1643 : We have the buck head=0x21106b0 call=0x21106b0
2012-08-28 17:14:56.027+0000: 9979: debug : virEventPollUpdateHandle:146 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupHandles:549 : Cleanup 2
2012-08-28 17:14:56.027+0000: 9979: debug : virEventPollInterruptLocked:697 : Skip interrupt, 0 -1103665408
2012-08-28 17:14:56.027+0000: 9980: debug : virEventRunDefaultImpl:244 : running default event implementation
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupTimeouts:501 : Cleanup 0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used, releasing 0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCleanupHandles:549 : Cleanup 2
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollMakePollFDs:378 : Prepare n=0 w=1, f=4 e=1 d=0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollMakePollFDs:378 : Prepare n=1 w=2, f=6 e=0 d=0
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCalculateTimeout:320 : Calculate expiry of 0 timers
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollCalculateTimeout:346 : Timeout at 0 due in -1 ms
2012-08-28 17:14:56.027+0000: 9980: debug : virEventPollRunOnce:614 : EVENT_POLL_RUN: nhandles=1 timeout=-1

Comment 2 Richard W.M. Jones 2012-08-28 17:17:44 UTC

All the libvirt-related packages that are installed:

libvirt-0.10.0-0rc0.2.fc18.x86_64
libvirt-client-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-config-network-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-config-nwfilter-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-interface-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-libxl-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-lxc-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-network-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-nodedev-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-nwfilter-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-qemu-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-secret-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-storage-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-uml-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-driver-xen-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-kvm-0.10.0-0rc0.2.fc18.x86_64
libvirt-daemon-qemu-0.10.0-0rc0.2.fc18.x86_64
libvirt-debuginfo-0.10.0-0rc0.2.fc18.x86_64
libvirt-devel-0.10.0-0rc0.2.fc18.x86_64
libvirt-docs-0.10.0-0rc0.2.fc18.x86_64
libvirt-python-0.10.0-0rc0.2.fc18.x86_64

Comment 3 Richard W.M. Jones 2012-08-29 14:12:38 UTC

selinux is Enforcing.

Comment 4 Richard W.M. Jones 2012-08-30 12:33:27 UTC

Also happens upstream (git b3bd5d6c5).

Comment 5 Richard W.M. Jones 2012-08-30 13:13:12 UTC

So I looked into this and found that it was hanging connecting
to /run/user/1000/libvirt/libvirt-sock.  The other end of this
was connected to a libvirtd process running as me that had
hung indefinitely and couldn't be killed.  I eventually killed
it using 'kill -9' and am now able to run libvirt processes
as non-root.

Comment 6 Richard W.M. Jones 2012-08-30 13:29:38 UTC

jdenemar suggests:

14:23 < jdenemar> "thread apply all backtrace" gdb command

14:28 < jdenemar> rjones: also, could you add the following lines to ~/.config/libvirt/libvirtd.conf
14:28 < jdenemar> log_level = 1
14:28 < jdenemar> log_filters = "3:udev 3:util/json 3:event"
14:28 < jdenemar> log_outputs = "1:file:/somwhere/you/can/write/libvirtd.log"

Comment 7 Richard W.M. Jones 2012-08-31 15:05:41 UTC

Hanging again.  Here is the stack trace of the hung daemon.
At least one of the threads (#12) seems to be deadlocked
in some way.

Thread 18 (Thread 0x7fa076997700 (LWP 23997)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f35190)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 17 (Thread 0x7fa076196700 (LWP 23998)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f354b0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 16 (Thread 0x7fa075995700 (LWP 23999)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f35190)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 15 (Thread 0x7fa075194700 (LWP 24000)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f354b0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 14 (Thread 0x7fa074993700 (LWP 24001)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f35190)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 13 (Thread 0x7fa074192700 (LWP 24002)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45198, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce9b in virThreadPoolWorker (opaque=opaque@entry=0x1f354b0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 12 (Thread 0x7fa073991700 (LWP 24003)):
#0  0x00000030d0e0de4d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000030d0e09ca6 in _L_lock_840 () from /lib64/libpthread.so.0
#2  0x00000030d0e09ba8 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007fa07727c9c5 in virMutexLock (m=<optimized out>)
    at util/threads-pthread.c:85
#4  0x00007fa0772ac9b9 in virDomainObjLock (obj=<optimized out>)
    at conf/domain_conf.c:14011
#5  0x00007fa06f34b2bc in qemuProcessHandleMonitorDestroy (mon=0x7fa0580c3850, 
    vm=0x7fa0580cd080) at qemu/qemu_process.c:1019
#6  0x00007fa06f35b952 in qemuMonitorDispose (obj=0x7fa0580c3850)
    at qemu/qemu_monitor.c:249
#7  0x00007fa077284723 in virObjectUnref (anyobj=<optimized out>)
    at util/virobject.c:139
#8  0x00007fa06f35c7e5 in qemuMonitorClose (mon=<optimized out>)
    at qemu/qemu_monitor.c:818
#9  0x00007fa06f35087d in qemuProcessStop (driver=driver@entry=0x7fa068076990, 
    vm=vm@entry=0x7fa0580cd080, 
    reason=reason@entry=VIR_DOMAIN_SHUTOFF_DESTROYED, flags=flags@entry=0)
    at qemu/qemu_process.c:4102
#10 0x00007fa06f389b2f in qemuDomainDestroyFlags (dom=<optimized out>, 
    flags=<optimized out>) at qemu/qemu_driver.c:1999
#11 0x00007fa0772f7531 in virDomainDestroyFlags (
    domain=domain@entry=0x7fa0600080b0, flags=0) at libvirt.c:2253
#12 0x00000000004133ad in remoteDispatchDomainDestroyFlags (
    args=0x7fa0600080f0, rerr=0x7fa073990c70, client=<optimized out>, 
    server=<optimized out>, msg=<optimized out>) at remote_dispatch.h:1137
#13 remoteDispatchDomainDestroyFlagsHelper (server=<optimized out>, 
    client=<optimized out>, msg=<optimized out>, rerr=0x7fa073990c70, 
    args=0x7fa0600080f0, ret=<optimized out>) at remote_dispatch.h:1115
#14 0x00007fa077354686 in virNetServerProgramDispatchCall (msg=0x1f777d0, 
    client=0x20d94c0, server=0x1f43da0, prog=0x1f68ff0)
    at rpc/virnetserverprogram.c:424
#15 virNetServerProgramDispatch (prog=0x1f68ff0, 
    server=server@entry=0x1f43da0, client=0x20d94c0, msg=0x1f777d0)
    at rpc/virnetserverprogram.c:297
#16 0x00007fa077350691 in virNetServerProcessMsg (msg=<optimized out>, 
    prog=<optimized out>, client=<optimized out>, srv=0x1f43da0)
    at rpc/virnetserver.c:170
#17 virNetServerHandleJob (jobOpaque=<optimized out>, opaque=0x1f43da0)
    at rpc/virnetserver.c:191
#18 0x00007fa07727cdde in virThreadPoolWorker (opaque=opaque@entry=0x1f35190)
    at util/threadpool.c:144
#19 0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#20 0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#21 0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 11 (Thread 0x7fa073190700 (LWP 24004)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45198, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce9b in virThreadPoolWorker (opaque=opaque@entry=0x1f354b0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7fa07298f700 (LWP 24005)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45198, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce9b in virThreadPoolWorker (opaque=opaque@entry=0x1f35190)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7fa07218e700 (LWP 24006)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45198, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce9b in virThreadPoolWorker (opaque=opaque@entry=0x1f354b0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7fa06cbe7700 (LWP 2533)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f6ef20)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7fa03ffff700 (LWP 2535)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f6bf00)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x7fa03f7fe700 (LWP 2536)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f6e010)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7fa03effd700 (LWP 2537)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f76ba0)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7fa03e7fc700 (LWP 2538)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f77040)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7fa03dffb700 (LWP 2539)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f6f070)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7fa03d7fa700 (LWP 2540)):
#0  0x00000030d0e0b5e5 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1  0x00007fa07727ca36 in virCondWait (c=c@entry=0x1f45100, 
    m=m@entry=0x1f450d8) at util/threads-pthread.c:117
#2  0x00007fa07727ce7b in virThreadPoolWorker (opaque=opaque@entry=0x1f72650)
    at util/threadpool.c:103
#3  0x00007fa07727c869 in virThreadHelper (data=<optimized out>)
    at util/threads-pthread.c:161
#4  0x00000030d0e07d15 in start_thread () from /lib64/libpthread.so.0
#5  0x00000030d0af196d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7fa076db9840 (LWP 23996)):
#0  0x00000030d0e0de4d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00000030d0e09ca6 in _L_lock_840 () from /lib64/libpthread.so.0
#2  0x00000030d0e09ba8 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007fa07727c9c5 in virMutexLock (m=<optimized out>)
    at util/threads-pthread.c:85
#4  0x00007fa06f349235 in qemuDriverLock (driver=<optimized out>)
    at qemu/qemu_conf.c:67
#5  0x00007fa06f38b27d in qemudClose (conn=0x7fa050000e30)
    at qemu/qemu_driver.c:1074
#6  0x00007fa0772edb7f in virConnectDispose (obj=0x7fa050000e30)
    at datatypes.c:144
#7  0x00007fa077284723 in virObjectUnref (anyobj=anyobj@entry=0x7fa050000e30)
    at util/virobject.c:139
#8  0x00007fa0772f5bb8 in virConnectClose (conn=0x7fa050000e30)
    at libvirt.c:1455
#9  0x00000000004281f7 in remoteClientFreeFunc (data=<optimized out>)
    at remote.c:651
#10 0x00007fa0773513ee in virNetServerClientDispose (obj=0x1f77c50)
    at rpc/virnetserverclient.c:590
#11 0x00007fa077284723 in virObjectUnref (anyobj=<optimized out>)
    at util/virobject.c:139
#12 0x00007fa0773589ca in virNetSocketEventFree (opaque=opaque@entry=0x20d8c00)
    at rpc/virnetsocket.c:1519
#13 0x00007fa07726baf8 in virEventPollCleanupHandles ()
    at util/event_poll.c:567
#14 0x00007fa07726c633 in virEventPollRunOnce () at util/event_poll.c:603
#15 0x00007fa07726b687 in virEventRunDefaultImpl () at util/event.c:247
#16 0x00007fa07735104d in virNetServerRun (srv=0x1f43da0)
    at rpc/virnetserver.c:751
#17 0x000000000040bebd in main (argc=<optimized out>, argv=<optimized out>)
    at libvirtd.c:1332

Comment 8 Richard W.M. Jones 2012-08-31 15:08:00 UTC

I sort of know what happened this time.  I was running
the very aggressive libvirt parallel mount-local test
(https://github.com/libguestfs/libguestfs/tree/b17d1896168bed2dc4c8c82bc368e79e10b14457/tests/mount-local)

The test was either hanging, or was taking a very very long
time to run (much longer than it would normally do), and
I killed the test.

I didn't notice that libvirtd was hung until some time later,
but I'm fairly sure this is what happened.

Comment 9 Cole Robinson 2013-01-27 21:19:50 UTC

I'm going to assume that since this involves weirdness in the Destroy() path that 877110 might help, so duping to that.

*** This bug has been marked as a duplicate of bug 877110 ***

Note You need to log in before you can comment on or make changes to this bug.