Bug 1003088

Summary: libvirt cannot open user connection in Rawhide: "libvirt: XML-RPC error : Cannot recv data: Connection reset by peer"
Product: [Fedora] Fedora Reporter: Richard W.M. Jones <rjones>
Component: libvirtAssignee: Libvirt Maintainers <libvirt-maint>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: berrange, clalancette, itamar, jforbes, jyang, laine, libvirt-maint, veillard, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-09-02 14:45:24 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On: 1003495    
Bug Blocks: 910269    
Attachments:
Description Flags
main.c
none
test.spec
none
build.log
none
strace -f output when the error occurs none

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.