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
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: | libvirt | Assignee: | Libvirt Maintainers <libvirt-maint> | ||||||||||
Status: | CLOSED RAWHIDE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||||||
Severity: | unspecified | Docs Contact: | |||||||||||
Priority: | unspecified | ||||||||||||
Version: | rawhide | CC: | 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: | |||||||||||
Embargoed: | |||||||||||||
Bug Depends On: | 1003495 | ||||||||||||
Bug Blocks: | 910269 | ||||||||||||
Attachments: |
|
Description
Richard W.M. Jones
2013-08-30 18:08:47 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. Still happens in Koji: http://kojipkgs.fedoraproject.org//work/tasks/6677/5876677/build.log I wonder what the difference could be? Builds fine in mock too, so ... throws arm up in despair. 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 ... 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. Created attachment 792650 [details]
main.c
Minimal test case (source file).
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
Created attachment 792653 [details]
build.log
build.log from Koji scratch build showing the failure.
Comment on attachment 792650 [details]
main.c
In fact this is NOT a definitive test.
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 Created attachment 792675 [details]
strace -f output when the error occurs
(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. 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 Opened a bug against fontconfig (bug 1003495). Appears to be fixed now. |