1003088 – libvirt cannot open user connection in Rawhide: "libvirt: XML-RPC error : Cannot recv data: Connection reset by peer"

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1003088 - libvirt cannot open user connection in Rawhide: "libvirt: XML-RPC error : Cannot recv data: Connection reset by peer"

Summary: libvirt cannot open user connection in Rawhide: "libvirt: XML-RPC error : Can...

Keywords:
Status:	CLOSED RAWHIDE
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	libvirt
Sub Component:
Version:	rawhide
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:	1003495
Blocks:	TRACKER-bugs-affecting-libguestfs
TreeView+	depends on / blocked

Reported:	2013-08-30 18:08 UTC by Richard W.M. Jones
Modified:	2013-09-02 14:45 UTC (History)
CC List:	9 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2013-09-02 14:45:24 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
main.c (258 bytes, text/plain) 2013-09-01 19:49 UTC, Richard W.M. Jones	no flags	Details
test.spec (292 bytes, text/plain) 2013-09-01 19:50 UTC, Richard W.M. Jones	no flags	Details
build.log (2.99 KB, text/plain) 2013-09-01 19:51 UTC, Richard W.M. Jones	no flags	Details
strace -f output when the error occurs (7.88 MB, text/plain) 2013-09-01 21:18 UTC, Richard W.M. Jones	no flags	Details
Show Obsolete (3) View All

Description Richard W.M. Jones 2013-08-30 18:08:47 UTC

Description of problem:

* Note this is probably not a libvirt bug since libvirt hasn't
* been updated recently in Rawhide.  I will continue to look at
* this and may reassign to whatever component is really responsible.

libvirt virConnectOpenAuth fails with URI = NULL and non-root user.
It appears that libvirt cannot talk to the user libvirtd process.
The error is:

libvirt: XML-RPC error : Cannot recv data: Connection reset by peer

The libguestfs code which is being run is:

https://github.com/libguestfs/libguestfs/blob/master/src/libvirt-auth.c#L162

The full log is:

http://koji.fedoraproject.org/koji/getfile?taskID=5874876&name=build.log

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

libvirt-1.1.1-3.fc20.x86_64
kernel-3.11.0-0.rc7.git2.1.fc21.x86_64
glibc-2.18-6.fc21.x86_64
libguestfs-1:1.23.19-1.fc21 (being built)

How reproducible:

Tried it twice, failed both times.

Steps to Reproduce:
1. Update a VM to latest rawhide.
2. Attempt to run libguestfs tests.

Comment 1 Richard W.M. Jones 2013-08-31 13:14:40 UTC

I cannot reproduce this in a local VM w/ precisely the same
package versions as above.  I have kicked off another Koji
build in case it was some Koji weirdness.

Comment 2 Richard W.M. Jones 2013-08-31 13:31:38 UTC

Still happens in Koji:
http://kojipkgs.fedoraproject.org//work/tasks/6677/5876677/build.log

I wonder what the difference could be?

Comment 3 Richard W.M. Jones 2013-08-31 14:13:54 UTC

Builds fine in mock too, so ... throws arm up in despair.

Comment 4 Richard W.M. Jones 2013-09-01 17:49:38 UTC

Now the same thing has started happening in Fedora 20:

http://kojipkgs.fedoraproject.org//work/tasks/9678/5879678/build.log

I bet money they've broken the kernel ...

Comment 5 Richard W.M. Jones 2013-09-01 19:48:11 UTC

Now I've put together a minimal test case, which proves that
it's got nothing to do with libguestfs.  The test case is
just a short program that does:

int
main ()
{
  virConnectPtr conn;

  conn = virConnectOpenAuth (NULL, virConnectAuthPtrDefault, 0);
  printf ("conn = %p\n", conn);
  exit (conn != NULL ? EXIT_SUCCESS : EXIT_FAILURE);
}

Failure is when conn == NULL.

This fails in a scratch build in Koji, although does not fail
when running my local tests.

Comment 6 Richard W.M. Jones 2013-09-01 19:49:17 UTC

Created attachment 792650 [details]
main.c

Minimal test case (source file).

Comment 7 Richard W.M. Jones 2013-09-01 19:50:40 UTC

Created attachment 792652 [details]
test.spec

Minimal test case (spec file), so you can build this in Koji.
Note you will need a Fedora packager account.

rpmbuild -ba --define "_sourcedir $(pwd)" test.spec
koji build --scratch rawhide $HOME/rpmbuild/SRPMS/test-0-1.src.rpm

Comment 8 Richard W.M. Jones 2013-09-01 19:51:12 UTC

Created attachment 792653 [details]
build.log

build.log from Koji scratch build showing the failure.

Comment 9 Richard W.M. Jones 2013-09-01 20:12:40 UTC

Comment on attachment 792650 [details]
main.c

In fact this is NOT a definitive test.

Comment 10 Richard W.M. Jones 2013-09-01 20:39:22 UTC

Here is the libguestfs compile with LIBVIRT_DEBUG=1:

2013-09-01 20:36:24.290+0000: 20322: debug : virGetVersion:939 : libVir=0x7fff4e2a5698, type=(null), typeVer=(nil)
libguestfs: libvirt version = 1001001 (1.1.1)
libguestfs: [00000ms] connect to libvirt
libguestfs: opening libvirt handle: URI = NULL, auth = virConnectAuthPtrDefault, flags = 0
2013-09-01 20:36:24.290+0000: 20322: debug : virConnectOpenAuth:1457 : name=(null), auth=0x7f51f50a66a0, flags=0
2013-09-01 20:36:24.290+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6a590 classname=virConnect
2013-09-01 20:36:24.290+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6a6c0 classname=virConnectCloseCallbackData
2013-09-01 20:36:24.290+0000: 20322: debug : do_open:1173 : no name, allowing driver auto-select
2013-09-01 20:36:24.290+0000: 20322: debug : do_open:1215 : trying driver 0 (Test) ...
2013-09-01 20:36:24.290+0000: 20322: debug : do_open:1222 : driver 0 Test returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 1 (OPENVZ) ...
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1222 : driver 1 OPENVZ returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 2 (VMWARE) ...
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1222 : driver 2 VMWARE returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 3 (PHYP) ...
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1222 : driver 3 PHYP returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 4 (ESX) ...
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1222 : driver 4 ESX returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 5 (Hyper-V) ...
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1222 : driver 5 Hyper-V returned DECLINED
2013-09-01 20:36:24.291+0000: 20322: debug : do_open:1215 : trying driver 6 (remote) ...
2013-09-01 20:36:24.291+0000: 20322: debug : remoteConnectOpen:998 : Auto-probe remote URI
2013-09-01 20:36:24.291+0000: 20322: debug : remoteConnectOpen:1001 : Auto-spawn user daemon instance
2013-09-01 20:36:24.291+0000: 20322: debug : doRemoteOpen:599 : proceeding with name = 
2013-09-01 20:36:24.291+0000: 20322: debug : doRemoteOpen:608 : Connecting with transport 1
2013-09-01 20:36:24.291+0000: 20322: debug : doRemoteOpen:699 : Proceeding with sockname /builddir/.cache/libvirt/libvirt-sock
2013-09-01 20:36:24.291+0000: 20322: debug : virNetSocketNewConnectUNIX:555 : Connection refused for /builddir/.cache/libvirt/libvirt-sock, trying to spawn /usr/sbin/libvirtd
2013-09-01 20:36:24.291+0000: 20322: debug : virCommandRunAsync:2237 : About to run LC_ALL=C LD_LIBRARY_PATH=/builddir/build/BUILD/libguestfs-1.23.20/ruby/ext/guestfs:/builddir/build/BUILD/libguestfs-1.23.20/src/.libs:/builddir/build/BUILD/libguestfs-1.23.20/gobject/.libs PATH=/builddir/build/BUILD/libguestfs-1.23.20/erlang:/builddir/build/BUILD/libguestfs-1.23.20/fuse:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/sbin:/builddir/.local/bin:/builddir/bin HOME=/builddir USER=mockbuild LOGNAME=mockbuild /usr/sbin/libvirtd --timeout=30
2013-09-01 20:36:24.291+0000: 20322: debug : virFileClose:90 : Closed fd 5
2013-09-01 20:36:24.291+0000: 20322: debug : virCommandRunAsync:2242 : Command result 0, with PID 20383
2013-09-01 20:36:24.291+0000: 20383: debug : virFileClose:90 : Closed fd 3
2013-09-01 20:36:24.291+0000: 20383: debug : virFileClose:90 : Closed fd 4
2013-09-01 20:36:24.293+0000: 20322: debug : virCommandRun:2111 : Result status 0, stdout: '(null)' stderr: '(null)'
2013-09-01 20:36:24.393+0000: 20322: debug : virNetSocketNew:155 : localAddr=0x7fff4e2a50c0 remoteAddr=0x7fff4e2a5150 fd=4 errfd=-1 pid=0
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6bc20 classname=virNetSocket
2013-09-01 20:36:24.393+0000: 20322: debug : virNetSocketNew:205 : RPC_SOCKET_NEW: sock=0x7f51f8c6bc20 fd=4 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6be00 classname=virNetClient
2013-09-01 20:36:24.393+0000: 20322: debug : virNetClientNew:326 : RPC_CLIENT_NEW: client=0x7f51f8c6be00 sock=0x7f51f8c6bc20
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6be00
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6bc20
2013-09-01 20:36:24.393+0000: 20322: debug : virNetSocketAddIOCallback:1739 : Failed to register watch on socket 0x7f51f8c6bc20
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6bc20
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6be00
2013-09-01 20:36:24.393+0000: 20322: debug : doRemoteOpen:778 : Failed to add event watch, disabling events and support for keepalive messages
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6a6c0
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6ac40 classname=virNetClientProgram
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6b960 classname=virNetClientProgram
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectNew:199 : OBJECT_NEW: obj=0x7f51f8c6b9d0 classname=virNetClientProgram
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6ac40
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6b960
2013-09-01 20:36:24.393+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6b9d0
2013-09-01 20:36:24.393+0000: 20322: debug : doRemoteOpen:816 : Trying authentication
2013-09-01 20:36:24.393+0000: 20322: debug : virNetMessageNew:44 : msg=0x7f51f8c6aa00 tracked=0
2013-09-01 20:36:24.393+0000: 20322: debug : virNetMessageEncodePayload:373 : Encode length as 28
2013-09-01 20:36:24.393+0000: 20322: debug : virNetClientSendInternal:1952 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f51f8c6be00 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
2013-09-01 20:36:24.393+0000: 20322: debug : virNetClientCallNew:1905 : New call 0x7f51f8c6ad10: msg=0x7f51f8c6aa00, expectReply=1, nonBlock=0
2013-09-01 20:36:24.393+0000: 20322: debug : virNetClientIO:1714 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil)
2013-09-01 20:36:24.393+0000: 20322: debug : virNetClientIO:1773 : We have the buck head=0x7f51f8c6ad10 call=0x7f51f8c6ad10
2013-09-01 20:36:24.393+0000: 20322: debug : virNetSocketUpdateIOCallback:1760 : Watch not registered on socket 0x7f51f8c6bc20
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientMarkClose:633 : client=0x7f51f8c6be00, reason=0
2013-09-01 20:36:24.402+0000: 20322: debug : virNetSocketRemoveIOCallback:1775 : Watch not registered on socket 0x7f51f8c6bc20
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientIOEventLoopPassTheBuck:1420 : Giving up the buck 0x7f51f8c6ad10
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientIOEventLoopPassTheBuck:1434 : No thread to pass the buck to
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientCloseLocked:646 : client=0x7f51f8c6be00, sock=0x7f51f8c6bc20, reason=0
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6bc20
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6bc20
2013-09-01 20:36:24.402+0000: 20322: debug : virNetSocketDispose:1002 : RPC_SOCKET_DISPOSE: sock=0x7f51f8c6bc20
2013-09-01 20:36:24.402+0000: 20322: debug : virFileClose:90 : Closed fd 4
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectRef:293 : OBJECT_REF: obj=0x7f51f8c6be00
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6be00
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientIO:1803 : All done with our call head=(nil) call=0x7f51f8c6ad10 rv=-1
2013-09-01 20:36:24.402+0000: 20322: debug : virNetMessageFree:72 : msg=0x7f51f8c6aa00 nfds=0 cb=(nil)
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6ac40
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6b960
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6b9d0
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientCloseInternal:687 : client=0x7f51f8c6be00 wantclose=0
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6be00
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6be00
2013-09-01 20:36:24.402+0000: 20322: debug : virNetClientDispose:599 : RPC_CLIENT_DISPOSE: client=0x7f51f8c6be00
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6a6c0
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6ac40
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6ac40
2013-09-01 20:36:24.402+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6b960
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6b960
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6b9d0
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6b9d0
2013-09-01 20:36:24.403+0000: 20322: debug : virFileClose:90 : Closed fd 6
2013-09-01 20:36:24.403+0000: 20322: debug : virFileClose:90 : Closed fd 5
2013-09-01 20:36:24.403+0000: 20322: debug : virNetMessageClear:55 : msg=0x7f51f8c6be68 nfds=0
2013-09-01 20:36:24.403+0000: 20322: debug : do_open:1222 : driver 6 remote returned ERROR
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6a590
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6a590
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:256 : OBJECT_UNREF: obj=0x7f51f8c6a6c0
2013-09-01 20:36:24.403+0000: 20322: debug : virObjectUnref:258 : OBJECT_DISPOSE: obj=0x7f51f8c6a6c0
libvirt: XML-RPC error : Cannot recv data: Connection reset by peer

Comment 11 Richard W.M. Jones 2013-09-01 21:18:13 UTC

Created attachment 792675 [details]
strace -f output when the error occurs

Comment 12 Richard W.M. Jones 2013-09-01 22:16:41 UTC

(In reply to Richard W.M. Jones from comment #11)
> Created attachment 792675 [details]
> strace -f output when the error occurs

PID 32693-32704 = libvirtd (multiple threads)
PID 32705 = dnsmasq --version
PID 32706 = dnsmasq --help
PID 32707 = rm command that libguestfs runs to clean up tempdir

It's all over somewhere between PID 32706 & PID 32707.

The last messages printed by libvirtd are:

2013-09-01 21:09:05.903+0000: 32704: error : virDBusGetSystemBus:87 : internal error: Unable to get DBus system bus connection: Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
2013-09-01 21:09:05.903+0000: 32704: warning : networkStateInitialize:440 : DBus not available, disabling firewalld support in bridge_driver: internal error: Unable to get DBus system bus connection: Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
2013-09-01 21:09:06.548+0000: 32704: error : virDBusGetSystemBus:87 : internal error: Unable to get DBus system bus connection: Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
2013-09-01 21:09:06.596+0000: 32704: error : qemuStateInit
ialize:626 : Failed to create lib dir '/builddir/.config/libvirt/qemu/lib': Permission denied
2013-09-01 21:09:06.597+0000: 32704: error : virStateInitialize:838 : Initialization of QEMU state driver failed: internal error: Unable to get DBus system bus connection: Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
2013-09-01 21:09:06.597+0000: 32704: error : daemonRunStateInit:905 : Driver state initialization failed

The dbus ones appear to be warnings.

The failure to create /builddir/.config/libvirt/qemu/lib is because
of this:

[pid 32704] stat("/builddir/.config", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 32704] mkdir("/builddir/.config/libvirt", 0777) = -1 EACCES (Permission denied)

This is Koji, so SELinux is likely to be disabled.  Unfortunately
the useful stat output has been truncated.

Previous calls to create files under /builddir/.cache are successful:

[pid 32704] mkdir("/builddir/.cache/libvirt/qemu", 0777) = 0
[pid 32704] mkdir("/builddir/.cache/libvirt/qemu/run", 0777) = 0

but there are no previous calls trying to make anything in /builddir/.config
so that's inconclusive.

Comment 13 Richard W.M. Jones 2013-09-01 22:38:26 UTC

OK, guess this might explain things:

+ ls -al /builddir
total 36
drwx------.  5 mockbuild mockbuild 4096 Sep  1 22:35 .
dr-xr-xr-x. 18 root      root      4096 Sep  1 22:23 ..
-rwxr-xr-x.  1 mockbuild mockbuild   18 Aug  9 12:08 .bash_logout
-rwxr-xr-x.  1 mockbuild mockbuild  193 Aug  9 12:08 .bash_profile
-rwxr-xr-x.  1 mockbuild mockbuild  231 Aug  9 12:08 .bashrc
drwxr-xr-x.  3 mockbuild mockbuild 4096 Sep  1 22:35 .cache
drwxr-xr-x.  3 root      root      4096 Sep  1 22:24 .config
-rw-rw-r--.  1 mockbuild mockbuild  211 Sep  1 22:23 .rpmmacros
drwxr-xr-x.  9 mockbuild mockbuild 4096 Sep  1 22:23 build

+ ls -al /builddir/.config
total 12
drwxr-xr-x. 3 root      root      4096 Sep  1 22:24 .
drwx------. 5 mockbuild mockbuild 4096 Sep  1 22:35 ..
drwxr-xr-x. 2 root      root      4096 Sep  1 22:24 fontconfig

Comment 14 Richard W.M. Jones 2013-09-02 08:00:30 UTC

Opened a bug against fontconfig (bug 1003495).

Comment 15 Richard W.M. Jones 2013-09-02 14:45:24 UTC

Appears to be fixed now.

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