Bug 1190669

Summary:	Support virt-v2v conversion of Windows > 7
Product:	Red Hat Enterprise Linux 7	Reporter:	Richard W.M. Jones <rjones>
Component:	libguestfs	Assignee:	Richard W.M. Jones <rjones>
Status:	CLOSED ERRATA	QA Contact:	Virtualization Bugs <virt-bugs>
Severity:	medium	Docs Contact:	Jiri Herrmann <jherrman>
Priority:	urgent
Version:	7.2	CC:	alfonsi.alex, angelo.lisco, bmcclain, byount, cinglese, colin.coe, dlamotta, dornelas, echen, ekin.meroglu, feoff3, gklein, jsuchane, juzhou, meverett, michal.skrivanek, mkalinin, mxie, mzhan, nobody, obockows, ptoscano, pvilayat, rjones, sherold, snagar, tzheng, ycui
Target Milestone:	rc
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:	V2V
Fixed In Version:	libguestfs-1.32.2-3.el7	Doc Type:	Release Note
Doc Text:	virt-v2v and virt-p2v add support for latest Windows releases The virt-v2v utility now includes support for converting virtual machines that use Windows 8, 8.1 and 10, and Windows Server 2012 and 2012R2 from the VMWare hypervisor to run on KVM, Red Hat Enterprise Virtualization, and OpenStack. In addition, the virt-p2v utility now includes support for converting physical machines that use the mentioned Windows systems to virtual machines compatible with KVM, Red Hat Enterprise Virtualization, and OpenStack.	Story Points:	---
Clone Of:
Clones:	1277738 (view as bug list)		Environment:
Last Closed:	2016-11-03 17:49:28 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:	1218766
Bug Blocks:	1213324, 1213691, 1288337

Description Richard W.M. Jones 2015-02-09 11:59:29 UTC

Description of problem:

Currently we only support Windows <= 7.

In theory we should be able to support later versions of Windows,
and we have virtio-win drivers for later versions, but when both
I tried it and QA tried it, it didn't work.

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

libguestfs 1.28.1

How reproducible:

100%

Steps to Reproduce:
1. Try to convert any Windows > 7 guest.

Additional info:

The was previously a rather long, rambling bug about this:
https://bugzilla.redhat.com/show_bug.cgi?id=1145908

Comment 1 Richard W.M. Jones 2015-02-09 12:00:23 UTC

*** Bug 1145908 has been marked as a duplicate of this bug. ***

Comment 2 Richard W.M. Jones 2015-04-10 12:56:33 UTC

Patch pushed upstream.  It's not very heavily tested yet
(only on Windows 8.1 & equivalent versions)

https://github.com/libguestfs/libguestfs/commit/2817824bd34e30fe6a2eeb65105067bd058f1fac

Comment 3 Richard W.M. Jones 2015-04-11 15:41:14 UTC

The previous commit omitted documentation.  The full set of
commits required is:

2817824bd34e30fe6a2eeb65105067bd058f1fac
80fcbe6eee209c8c94dc99f137e965432da99dd5

Comment 5 tingting zheng 2015-04-20 08:09:47 UTC

Tested with:
libguestfs-1.28.1-1.25.el7.x86_64
virt-v2v-1.28.1-1.25.el7.x86_64
virtio-win-1.7.4-1.el7.noarch
libguestfs-winsupport-7.1-4.el7.x86_64

Test conversion win8,win8.1,win2012,win2012R2 from xen/esx.
win8 from xen:
# virt-v2v -ic xen+ssh://10.66.106.64 -os default -b br1 xen-hvm-win8-x86_64 -of raw
# virt-v2v -ic xen+ssh://10.66.106.64 -o rhev -os 10.66.90.115:/vol/v2v_auto/iscsi_export -n rhevm xen-hvm-win8-i386 -of raw

win8.1 from esx5.5:
# virt-v2v -ic vpx://root.111.25/tzheng-demo/10.66.106.63/?no_verify=1 esx5.5-win8.1-x86_64 --password-file /tmp/passwd2
# virt-v2v -ic vpx://root.111.25/tzheng-demo/10.66.106.63/?no_verify=1 esx5.5-win8.1-i386 --password-file /tmp/passwd2

win2012 from esx5.5:
# virt-v2v -ic vpx://root.111.25/tzheng-demo/10.66.106.63/?no_verify=1  --password-file /tmp/passwd2 -b br1  esx5.5-win2012-x86_64

win2012R2 from esx5.5:
# virt-v2v -ic vpx://root.111.25/tzheng-demo/10.66.106.63/?no_verify=1  --password-file /tmp/passwd2 -n rhevm -b br1 esx5.5-win2012R2-x86_64 
# virt-v2v -ic vpx://root.111.25/tzheng-demo/10.66.106.63/?no_verify=1  --password-file /tmp/passwd2 -b rhevm  esx5.5-win2012R2-x86_64 -o rhev -os 10.66.90.115:/vol/v2v_auto/auto_export

All the above guests can be converted successfully and guests can be booted successfully.

Refer to the above comments,move the bug to VERIFIED.

Comment 8 Richard W.M. Jones 2015-06-25 11:58:32 UTC

I've reverted this commit (starting from libguestfs-1.28.1-1.40.el7)
and postponed the feature to RHEL 7.3.

Comment 10 Richard W.M. Jones 2015-07-07 14:13:37 UTC

For reference, the following patch was added to RHEL 7.2
so virt-v2v will refuse to convert any Windows > 7.

https://github.com/libguestfs/libguestfs/commit/7d399354c0a833f0138632883175ba1c6b54af0b

Comment 11 zhoujunqin 2015-07-08 06:31:37 UTC

Test with:
libvirt-1.2.17-1.el7.x86_64
libguestfs-1.28.1-1.46.el7.x86_64
virt-v2v-1.28.1-1.46.el7.x86_64
libguestfs-winsupport-7.2-1.el7.x86_64
libguestfs-xfs-1.28.1-1.46.el7.x86_64

Test conversion win8,win8.1,win2012,win2012R2 from xen/esx.

win8 from xen:
# virt-v2v -ic xen+ssh://10.66.106.64 -os default -b br1 xen-hvm-win8-x86_64 -of raw
# virt-v2v -ic xen+ssh://10.66.106.64 -o rhev -os 10.66.90.115:/vol/v2v_auto/auto_export -n rhevm xen-hvm-win8-i386 -of raw


win8.1 from esx5.1:
virt-v2v -ic  vpx://root.4.103/tzheng-demo/10.66.4.153/?no_verify=1 --password-file /tmp/passwd2 esx5.1-win8-x86_64 
# virt-v2v -ic  vpx://root.4.103/tzheng-demo/10.66.4.153/?no_verify=1 --password-file /tmp/passwd2 esx5.1-win8-i386


win2012 from esx6.0:
# virt-v2v -ic vpx://root.72.112/data/10.66.72.49/?no_verify=1 --password-file /tmp/passwd2 esx6.0-win2012-x86_64

win2012R2 from esx6.0:
# virt-v2v -ic vpx://root.72.112/data/10.66.72.49/?no_verify=1 --password-file /tmp/passwd2 esx6.0-win2012r2-x86_64 


# virt-v2v -ic vpx://root.72.112/data/10.66.72.49/?no_verify=1 --password-file /tmp/passwd2 esx6.0-win2012r2-x86_64 -o rhev -os 10.66.90.115:/vol/v2v_auto/auto_export -on esx6.0-win2012r2-x86_64-juzhou


All the above guests cannot be converted to target with get error:
...
virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
(see https://bugzilla.redhat.com/1190669)

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

Comment 12 Alessandro 2015-11-03 22:49:13 UTC

When running:
virt-v2v -ic vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 -o libvirt -os virtimages "vmname" --password-file /tmp/password

[   0.0] Opening the source -i libvirt -ic vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 vmname
[   2.0] Creating an overlay to protect the source from being modified
[   3.0] Opening the overlay
^[[1;5D[  55.0] Initializing the target -o libvirt -os virtimages
[  55.0] Inspecting the overlay
[ 235.0] Checking for sufficient free disk space in the guest
[ 235.0] Estimating space required on target for each disk
[ 235.0] Converting Windows Server 2012 R2 Standard to run on KVM
virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
(see https://bugzilla.redhat.com/1190669)

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

ESXi host and vCenter Server version 5.5.

Is Windows Server 2012 R2 Standard still not supported for the conversion?
Will it be soon as well as Windows 8 and 10?

Libirt version:
libvirt-client-1.2.17-1.el7.x86_64

Virt-v2v version:
virt-v2v-1.28.1-1.48.el7.x86_64

Many Thanks!

Comment 13 tingting zheng 2015-11-04 04:26:13 UTC

(In reply to Alessandro from comment #12)
> When running:
> virt-v2v -ic vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 -o
> libvirt -os virtimages "vmname" --password-file /tmp/password
> 
> [   0.0] Opening the source -i libvirt -ic
> vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 vmname
> [   2.0] Creating an overlay to protect the source from being modified
> [   3.0] Opening the overlay
> ^[[1;5D[  55.0] Initializing the target -o libvirt -os virtimages
> [  55.0] Inspecting the overlay
> [ 235.0] Checking for sufficient free disk space in the guest
> [ 235.0] Estimating space required on target for each disk
> [ 235.0] Converting Windows Server 2012 R2 Standard to run on KVM
> virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
> (see https://bugzilla.redhat.com/1190669)
> 
> If reporting bugs, run virt-v2v with debugging enabled and include the 
> complete output:
> 
>   virt-v2v -v -x [...]
> 
> ESXi host and vCenter Server version 5.5.
> 
> Is Windows Server 2012 R2 Standard still not supported for the conversion?
> Will it be soon as well as Windows 8 and 10?

Yes,right now Win 2012R2,Win 8 and 10 are not supported,Windows < 7 and win2008R2 are supported.

It may be supported on rhel7.3.

Comment 14 Alessandro 2015-11-04 16:54:28 UTC

(In reply to tingting zheng from comment #13)
> (In reply to Alessandro from comment #12)
> > When running:
> > virt-v2v -ic vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 -o
> > libvirt -os virtimages "vmname" --password-file /tmp/password
> > 
> > [   0.0] Opening the source -i libvirt -ic
> > vpx://USER@vCenterServer/DC/Cluster/ESXiHost/?no_verify=1 vmname
> > [   2.0] Creating an overlay to protect the source from being modified
> > [   3.0] Opening the overlay
> > ^[[1;5D[  55.0] Initializing the target -o libvirt -os virtimages
> > [  55.0] Inspecting the overlay
> > [ 235.0] Checking for sufficient free disk space in the guest
> > [ 235.0] Estimating space required on target for each disk
> > [ 235.0] Converting Windows Server 2012 R2 Standard to run on KVM
> > virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
> > (see https://bugzilla.redhat.com/1190669)
> > 
> > If reporting bugs, run virt-v2v with debugging enabled and include the 
> > complete output:
> > 
> >   virt-v2v -v -x [...]
> > 
> > ESXi host and vCenter Server version 5.5.
> > 
> > Is Windows Server 2012 R2 Standard still not supported for the conversion?
> > Will it be soon as well as Windows 8 and 10?
> 
> Yes,right now Win 2012R2,Win 8 and 10 are not supported,Windows < 7 and
> win2008R2 are supported.
> 
> It may be supported on rhel7.3.

I am running libvirt and virt-v2v on a CentOS system. Will I just need to run an update command or do I need to create a new repository on my system?

Is there an approximate date for rhel7.3 release?
We are in the middle of a huge migration project and time is key.

Many thanks!

Comment 15 Richard W.M. Jones 2015-11-04 16:59:52 UTC

RHEL 7.2 is going to be released this month.

RHEL minor releases usually happen approx every 6 months.

There is a RHEL 7.3 preview repo available (not actually up to date
at the moment).  See:
https://www.redhat.com/archives/libguestfs/2015-September/msg00079.html

Windows conversions are complicated.  In Windows > 7, the method
Microsoft uses to install drivers completely changed.  So there's
a risk to using the new, mostly untested code.

Comment 16 Alessandro 2015-11-04 21:29:06 UTC

So, is 7.2 going to support 2012 or 8 and 10?
Would it be of help if I install and run a test using the preview repo to speed up the 7.3 version to be stable?

Comment 17 Richard W.M. Jones 2015-11-04 21:31:48 UTC

RHEL 7.2 supports Windows <= 7.

RHEL 7.3 *may* support later versions of Windows, if we get enough
time to test the current bug.  The code is upstream and in recent
Fedora, so you can test it yourself, but keep backups.

Comment 18 Alessandro 2015-11-04 21:51:25 UTC

Ok, thanks Richard!
I will clone my current environment and test 7.3.
Where do you want me to post eventual bugs for you to review?

Comment 19 Alessandro 2015-11-13 18:04:12 UTC

Just tested the new virt-v2v preview version and I still get this error:

[   0.0] Opening the source -i libvirt -ic vpx://DOMAIN%5cUSERNAME@zvCenterServerName/Data%20Center%20Name/Logical%20Folder/ClusterESXi/ESXiHost/?no_verify=1 conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)
[   2.5] Creating an overlay to protect the source from being modified
[   3.6] Opening the overlay

Message from syslogd@localhost at Nov 13 09:30:36 ...
 kernel:BUG: soft lockup - CPU#1 stuck for 22s! [qemu-kvm:8250]
[  69.0] Initializing the target -o libvirt -os virtimages
[  69.1] Inspecting the overlay
[ 196.1] Checking for sufficient free disk space in the guest
[ 196.1] Estimating space required on target for each disk
[ 196.1] Converting Windows Server 2012 R2 Standard to run on KVM
virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
(see https://bugzilla.redhat.com/1190669)

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

Version details:
Libvirt version:
libvirt-client-1.2.17-3.el7.x86_64

Virt-v2v version:
virt-v2v-1.31.7-2.el7.x86_64

libguestfs version:
1.31.7rhel=7,release=2.el7,libvirt

Comment 20 Alessandro 2015-11-13 18:22:28 UTC

DEBUG PART 1:
[root@CENTOS7 ~]# LIBVIRT_DEBUG=1 virt-v2v --dcpath 'Data%20Center%20Name' -ic vpx://DOMAIN%5cUSERNAME@zvCenterServerName/Data%20Center%20Name/Logical%20Folder/ClusterESXi/ESXiHost/?no_verify=1 -o libvirt -os virtimages "conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)" --password-file /root/Scripts/Passwd
2015-11-13 18:11:06.404+0000: 3945: info : libvirt version: 1.2.17, package: 3.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2015-07-30-06:50:09, x86-034.build.eng.bos.redhat.com)
2015-11-13 18:11:06.404+0000: 3945: debug : virGlobalInit:389 : register drivers
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:691 : driver=0x7fbbac7e7620 name=Test
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:702 : registering Test as driver 0
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:691 : driver=0x7fbbac7e9240 name=ESX
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:702 : registering ESX as driver 1
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:691 : driver=0x7fbbac7e80a0 name=remote
2015-11-13 18:11:06.404+0000: 3945: debug : virRegisterConnectDriver:702 : registering remote as driver 2
[   0.0] Opening the source -i libvirt -ic vpx://DOMAIN%5cUSERNAME@zvCenterServerName/Data%20Center%20Name/Logical%20Folder/ClusterESXi/ESXiHost/?no_verify=1 conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)
2015-11-13 18:11:06.407+0000: 3945: debug : virConnectOpenAuth:1339 : name=vpx://DOMAIN%5cUSERNAME@zvCenterServerName/Data%20Center%20Name/Logical%20Folder/ClusterESXi/ESXiHost/?no_verify=1, auth=0x7fffc8bf91a0, flags=0
2015-11-13 18:11:06.407+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x251a660 classname=virConnect
2015-11-13 18:11:06.407+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x251a7d0 classname=virConnectCloseCallbackData
2015-11-13 18:11:06.407+0000: 3945: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf'
2015-11-13 18:11:06.407+0000: 3945: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf
2015-11-13 18:11:06.407+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:06.408+0000: 3945: debug : do_open:1132 : name "vpx://DOMAIN%5cUSERNAME@zvCenterServerName/Data%20Center%20Name/Logical%20Folder/ClusterESXi/ESXiHost/?no_verify=1" to URI components:
  scheme vpx
  server vCenterServerName
  user DOMAIN\USERNAME
  port 0
  path /Data Center Name/Logical Folder/ClusterESXi/ESXiHost/

2015-11-13 18:11:06.408+0000: 3945: debug : do_open:1179 : trying driver 0 (Test) ...
2015-11-13 18:11:06.408+0000: 3945: debug : do_open:1194 : driver 0 Test returned DECLINED
2015-11-13 18:11:06.408+0000: 3945: debug : do_open:1179 : trying driver 1 (ESX) ...
2015-11-13 18:11:06.409+0000: 3945: debug : virAuthGetConfigFilePathURI:52 : Determining auth config file path
2015-11-13 18:11:06.409+0000: 3945: debug : virAuthGetConfigFilePathURI:79 : Checking for readability of '/root/.config/libvirt/auth.conf'
2015-11-13 18:11:06.409+0000: 3945: debug : virAuthGetConfigFilePathURI:88 : Checking for readability of '/etc/libvirt/auth.conf'
2015-11-13 18:11:06.409+0000: 3945: debug : virAuthGetConfigFilePathURI:97 : Using auth file '<null>'
2015-11-13 18:11:07.104+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25fe4a0 classname=virCaps
2015-11-13 18:11:07.110+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2606df0 classname=virDomainXMLOption
2015-11-13 18:11:07.110+0000: 3945: debug : do_open:1194 : driver 1 ESX returned SUCCESS
2015-11-13 18:11:07.110+0000: 3945: debug : virDomainLookupByUUIDString:380 : conn=0x251a660, uuidstr=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)
2015-11-13 18:11:07.110+0000: 3945: debug : virDomainLookupByName:416 : conn=0x251a660, name=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)
2015-11-13 18:11:07.155+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x262b910 classname=virDomain
2015-11-13 18:11:07.155+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x251a660
2015-11-13 18:11:07.155+0000: 3945: debug : virDomainGetState:2484 : dom=0x262b910, (VM: name=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e), uuid=420e6f38-1cd0-83cb-2774-305fbfd2b355), state=0x7fffc8bf9190, reason=0x7fffc8bf9194, flags=0
2015-11-13 18:11:07.177+0000: 3945: debug : virDomainGetXMLDesc:2575 : dom=0x262b910, (VM: name=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e), uuid=420e6f38-1cd0-83cb-2774-305fbfd2b355), flags=1
2015-11-13 18:11:07.708+0000: 3945: debug : virDomainFree:565 : dom=0x262b910, (VM: name=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e), uuid=420e6f38-1cd0-83cb-2774-305fbfd2b355)
2015-11-13 18:11:07.708+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x262b910
2015-11-13 18:11:07.708+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x262b910
2015-11-13 18:11:07.708+0000: 3945: debug : virDomainDispose:238 : release domain 0x262b910 conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e) 420e6f38-1cd0-83cb-2774-305fbfd2b355
2015-11-13 18:11:07.708+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x251a660
2015-11-13 18:11:07.708+0000: 3945: debug : virConnectClose:1384 : conn=0x251a660
2015-11-13 18:11:07.708+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x251a660
2015-11-13 18:11:07.708+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x251a660
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25fe4a0
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25fe4a0
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2606df0
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2606df0
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x251a7d0
2015-11-13 18:11:07.717+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x251a7d0
[   2.3] Creating an overlay to protect the source from being modified
[   3.1] Opening the overlay
[  23.2] Initializing the target -o libvirt -os virtimages
2015-11-13 18:11:29.633+0000: 3945: debug : virConnectOpenAuth:1339 : name=<null>, auth=0x7fbbac7e73e0, flags=1
2015-11-13 18:11:29.633+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25eca20 classname=virConnect
2015-11-13 18:11:29.633+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25d8060 classname=virConnectCloseCallbackData
2015-11-13 18:11:29.633+0000: 3945: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf'
2015-11-13 18:11:29.633+0000: 3945: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf
2015-11-13 18:11:29.633+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1136 : no name, allowing driver auto-select
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1179 : trying driver 0 (Test) ...
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1194 : driver 0 Test returned DECLINED
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1179 : trying driver 1 (ESX) ...
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1194 : driver 1 ESX returned DECLINED
2015-11-13 18:11:29.633+0000: 3945: debug : do_open:1179 : trying driver 2 (remote) ...
2015-11-13 18:11:29.633+0000: 3945: debug : remoteConnectOpen:1191 : Auto-probe remote URI
2015-11-13 18:11:29.633+0000: 3945: debug : doRemoteOpen:792 : proceeding with name = 
2015-11-13 18:11:29.633+0000: 3945: debug : doRemoteOpen:801 : Connecting with transport 1
2015-11-13 18:11:29.633+0000: 3945: debug : doRemoteOpen:893 : Proceeding with sockname /var/run/libvirt/libvirt-sock-ro
2015-11-13 18:11:29.634+0000: 3945: debug : virNetSocketNew:225 : localAddr=0x7fffc8bf8c60 remoteAddr=0x7fffc8bf8cf0 fd=4 errfd=-1 pid=0
2015-11-13 18:11:29.634+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2601a60 classname=virNetSocket
2015-11-13 18:11:29.634+0000: 3945: info : virNetSocketNew:276 : RPC_SOCKET_NEW: sock=0x2601a60 fd=4 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2015-11-13 18:11:29.634+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2601ca0 classname=virNetClient
2015-11-13 18:11:29.634+0000: 3945: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x2601ca0 sock=0x2601a60
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2601ca0
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2601a60
2015-11-13 18:11:29.634+0000: 3945: debug : virNetSocketAddIOCallback:1955 : Failed to register watch on socket 0x2601a60
2015-11-13 18:11:29.634+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601a60
2015-11-13 18:11:29.634+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601ca0
2015-11-13 18:11:29.634+0000: 3945: debug : doRemoteOpen:972 : Failed to add event watch, disabling events and support for keepalive messages
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x25d8060
2015-11-13 18:11:29.634+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2601eb0 classname=virNetClientProgram
2015-11-13 18:11:29.634+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2601f90 classname=virNetClientProgram
2015-11-13 18:11:29.634+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2602000 classname=virNetClientProgram
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2601eb0
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2601f90
2015-11-13 18:11:29.634+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2602000
2015-11-13 18:11:29.634+0000: 3945: debug : doRemoteOpen:1010 : Trying authentication
2015-11-13 18:11:29.634+0000: 3945: debug : virNetMessageNew:46 : msg=0x26022a0 tracked=0
2015-11-13 18:11:29.634+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.634+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
2015-11-13 18:11:29.634+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x26022a0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.634+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.634+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.634+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.638+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 36 total (32 more)
2015-11-13 18:11:29.638+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=36 prog=536903814 vers=1 proc=66 type=1 status=0 serial=0
2015-11-13 18:11:29.638+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.638+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.638+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetMessageFree:74 : msg=0x26022a0 nfds=0 cb=(nil)
2015-11-13 18:11:29.638+0000: 3945: debug : doRemoteOpen:1036 : Trying to open URI 
2015-11-13 18:11:29.638+0000: 3945: debug : virNetMessageNew:46 : msg=0x2601dd0 tracked=0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 40
2015-11-13 18:11:29.638+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=40 prog=536903814 vers=1 proc=1 type=0 status=0 serial=1
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x2601dd0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=1 proc=1 type=0 length=40 dispatch=(nil)
2015-11-13 18:11:29.638+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.638+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.639+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=1
2015-11-13 18:11:29.639+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.639+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageFree:74 : msg=0x2601dd0 nfds=0 cb=(nil)
2015-11-13 18:11:29.639+0000: 3945: debug : doRemoteOpen:1047 : Trying to query remote URI
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageNew:46 : msg=0x25ecfa0 tracked=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.639+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=110 type=0 status=0 serial=2
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x25ecfa0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=2 proc=110 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 48 total (44 more)
2015-11-13 18:11:29.639+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=48 prog=536903814 vers=1 proc=110 type=1 status=0 serial=2
2015-11-13 18:11:29.639+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.639+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageFree:74 : msg=0x25ecfa0 nfds=0 cb=(nil)
2015-11-13 18:11:29.639+0000: 3945: debug : doRemoteOpen:1055 : Auto-probed URI is qemu:///system
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageNew:46 : msg=0x2601dd0 tracked=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 32
2015-11-13 18:11:29.639+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=3
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x2601dd0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=3 proc=60 type=0 length=32 dispatch=(nil)
2015-11-13 18:11:29.639+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.639+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.640+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 32 total (28 more)
2015-11-13 18:11:29.640+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=3
2015-11-13 18:11:29.640+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.640+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.640+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetMessageFree:74 : msg=0x2601dd0 nfds=0 cb=(nil)
2015-11-13 18:11:29.640+0000: 3945: debug : do_open:1194 : driver 2 remote returned SUCCESS
2015-11-13 18:11:29.640+0000: 3945: debug : virConnectGetCapabilities:392 : conn=0x25eca20
2015-11-13 18:11:29.640+0000: 3945: debug : virNetMessageNew:46 : msg=0x25ed280 tracked=0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.640+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=7 type=0 status=0 serial=4
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25ecff0: msg=0x25ed280, expectReply=1, nonBlock=0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=4 proc=7 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.640+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25ecff0 call=0x25ecff0
2015-11-13 18:11:29.640+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.644+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 4036 total (4032 more)
2015-11-13 18:11:29.644+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=4036 prog=536903814 vers=1 proc=7 type=1 status=0 serial=4
2015-11-13 18:11:29.644+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.644+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.644+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25ecff0
2015-11-13 18:11:29.644+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.644+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.644+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25ecff0 rv=0
2015-11-13 18:11:29.644+0000: 3945: debug : virNetMessageFree:74 : msg=0x25ed280 nfds=0 cb=(nil)
2015-11-13 18:11:29.644+0000: 3945: debug : virConnectGetCapabilities:403 : conn=0x25eca20 ret=<capabilities>

  <host>
    <uuid>420ebeff-97b3-f8f8-1a96-4ccf39b8bc8a</uuid>
    <cpu>
      <arch>x86_64</arch>
      <model>Westmere</model>
      <vendor>Intel</vendor>
      <topology sockets='2' cores='2' threads='1'/>
      <feature name='invtsc'/>
      <feature name='rdtscp'/>
      <feature name='hypervisor'/>
      <feature name='avx'/>
      <feature name='osxsave'/>
      <feature name='xsave'/>
      <feature name='vmx'/>
      <feature name='pclmuldq'/>
      <feature name='ht'/>
      <feature name='ss'/>
      <feature name='ds'/>
      <feature name='vme'/>
      <pages unit='KiB' size='4'/>
      <pages unit='KiB' size='2048'/>
    </cpu>
    <power_management>
      <suspend_mem/>
      <suspend_disk/>
      <suspend_hybrid/>
    </power_management>
    <migration_features>
      <live/>
      <uri_transports>
        <uri_transport>tcp</uri_transport>
        <uri_transport>rdma</uri_transport>
      </uri_transports>
    </migration_features>
    <topology>
      <cells num='1'>
        <cell id='0'>
          <memory unit='KiB'>16776760</memory>
          <pages unit='KiB' size='4'>4194190</pages>
          <pages unit='KiB' size='2048'>0</pages>
          <distances>
            <sibling id='0' value='10'/>
          </distances>
          <cpus num='4'>
            <cpu id='0' socket_id='0' core_id='0' siblings='0'/>
            <cpu id='1' socket_id='0' core_id='1' siblings='1'/>
            <cpu id='2' socket_id='1' core_id='0' siblings='2'/>
            <cpu id='3' socket_id='1' core_id='1' siblings='3'/>
          </cpus>
        </cell>
      </cells>
    </topology>
    <secmodel>
      <model>selinux</model>
      <doi>0</doi>
      <baselabel type='kvm'>system_u:system_r:svirt_t:s0</baselabel>
      <baselabel type='qemu'>system_u:system_r:svirt_tcg_t:s0</baselabel>
    </secmodel>
    <secmodel>
      <model>dac</model>
      <doi>0</doi>
      <baselabel type='kvm'>+107:+107</baselabel>
      <baselabel type='qemu'>+107:+107</baselabel>
    </secmodel>
  </host>

  <guest>
    <os_type>hvm</os_type>
    <arch name='i686'>
      <wordsize>32</wordsize>
      <emulator>/usr/libexec/qemu-kvm</emulator>
      <machine maxCpus='240'>pc-i440fx-rhel7.0.0</machine>
      <machine canonical='pc-i440fx-rhel7.0.0' maxCpus='240'>pc</machine>
      <machine maxCpus='240'>rhel6.0.0</machine>
      <machine maxCpus='240'>rhel6.1.0</machine>
      <machine maxCpus='240'>rhel6.2.0</machine>
      <machine maxCpus='240'>rhel6.3.0</machine>
      <machine maxCpus='240'>rhel6.4.0</machine>
      <machine maxCpus='240'>rhel6.5.0</machine>
      <machine maxCpus='240'>rhel6.6.0</machine>
      <domain type='qemu'/>
      <domain type='kvm'>
        <emulator>/usr/libexec/qemu-kvm</emulator>
      </domain>
    </arch>
    <features>
      <cpuselection/>
      <deviceboot/>
      <disksnapshot default='off' toggle='no'/>
      <acpi default='on' toggle='yes'/>
      <apic default='on' toggle='no'/>
      <pae/>
      <nonpae/>
    </features>
  </guest>

  <guest>
    <os_type>hvm</os_type>
    <arch name='x86_64'>
      <wordsize>64</wordsize>
      <emulator>/usr/libexec/qemu-kvm</emulator>
      <machine maxCpus='240'>pc-i440fx-rhel7.0.0</machine>
      <machine canonical='pc-i440fx-rhel7.0.0' maxCpus='240'>pc</machine>
      <machine maxCpus='240'>rhel6.0.0</machine>
      <machine maxCpus='240'>rhel6.1.0</machine>
      <machine maxCpus='240'>rhel6.2.0</machine>
      <machine maxCpus='240'>rhel6.3.0</machine>
      <machine maxCpus='240'>rhel6.4.0</machine>
      <machine maxCpus='240'>rhel6.5.0</machine>
      <machine maxCpus='240'>rhel6.6.0</machine>
      <domain type='qemu'/>
      <domain type='kvm'>
        <emulator>/usr/libexec/qemu-kvm</emulator>
      </domain>
    </arch>
    <features>
      <cpuselection/>
      <deviceboot/>
      <disksnapshot default='off' toggle='no'/>
      <acpi default='on' toggle='yes'/>
      <apic default='on' toggle='no'/>
    </features>
  </guest>

</capabilities>

Comment 21 Alessandro 2015-11-13 18:23:27 UTC

DEBUG PART 2:
2015-11-13 18:11:29.647+0000: 3945: debug : virConnectClose:1384 : conn=0x25eca20
2015-11-13 18:11:29.647+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25eca20
2015-11-13 18:11:29.647+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25eca20
2015-11-13 18:11:29.647+0000: 3945: debug : virNetMessageNew:46 : msg=0x25ed4b0 tracked=0
2015-11-13 18:11:29.647+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.647+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=5
2015-11-13 18:11:29.647+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25ecde0: msg=0x25ed4b0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.647+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=5 proc=2 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.647+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25ecde0 call=0x25ecde0
2015-11-13 18:11:29.647+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.648+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.648+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2601ca0 len=28 prog=536903814 vers=1 proc=2 type=1 status=0 serial=5
2015-11-13 18:11:29.648+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x2601d08
2015-11-13 18:11:29.648+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25ecde0
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.648+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25ecde0 rv=0
2015-11-13 18:11:29.648+0000: 3945: debug : virNetMessageFree:74 : msg=0x25ed4b0 nfds=0 cb=(nil)
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientCloseInternal:695 : client=0x2601ca0 wantclose=0
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientMarkClose:638 : client=0x2601ca0, reason=3
2015-11-13 18:11:29.648+0000: 3945: debug : virNetSocketRemoveIOCallback:1991 : Watch not registered on socket 0x2601a60
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck (nil)
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.648+0000: 3945: debug : virNetClientCloseLocked:654 : client=0x2601ca0, sock=0x2601a60, reason=3
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601a60
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2601a60
2015-11-13 18:11:29.648+0000: 3945: info : virNetSocketDispose:1155 : RPC_SOCKET_DISPOSE: sock=0x2601a60
2015-11-13 18:11:29.648+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601ca0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2601ca0
2015-11-13 18:11:29.648+0000: 3945: info : virNetClientDispose:606 : RPC_CLIENT_DISPOSE: client=0x2601ca0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601eb0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601f90
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2602000
2015-11-13 18:11:29.648+0000: 3945: debug : virFileClose:102 : Closed fd 10
2015-11-13 18:11:29.648+0000: 3945: debug : virFileClose:102 : Closed fd 9
2015-11-13 18:11:29.648+0000: 3945: debug : virNetMessageClear:57 : msg=0x2601d08 nfds=0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601eb0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2601eb0
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601f90
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2601f90
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2602000
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2602000
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.648+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25d8060
2015-11-13 18:11:29.649+0000: 3945: debug : virConnectOpenAuth:1339 : name=<null>, auth=0x7fbbac7e73e0, flags=1
2015-11-13 18:11:29.649+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25ed280 classname=virConnect
2015-11-13 18:11:29.649+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25d8060 classname=virConnectCloseCallbackData
2015-11-13 18:11:29.649+0000: 3945: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf'
2015-11-13 18:11:29.649+0000: 3945: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf
2015-11-13 18:11:29.649+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1136 : no name, allowing driver auto-select
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1179 : trying driver 0 (Test) ...
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1194 : driver 0 Test returned DECLINED
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1179 : trying driver 1 (ESX) ...
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1194 : driver 1 ESX returned DECLINED
2015-11-13 18:11:29.649+0000: 3945: debug : do_open:1179 : trying driver 2 (remote) ...
2015-11-13 18:11:29.649+0000: 3945: debug : remoteConnectOpen:1191 : Auto-probe remote URI
2015-11-13 18:11:29.660+0000: 3945: debug : doRemoteOpen:792 : proceeding with name = 
2015-11-13 18:11:29.660+0000: 3945: debug : doRemoteOpen:801 : Connecting with transport 1
2015-11-13 18:11:29.660+0000: 3945: debug : doRemoteOpen:893 : Proceeding with sockname /var/run/libvirt/libvirt-sock-ro
2015-11-13 18:11:29.660+0000: 3945: debug : virNetSocketNew:225 : localAddr=0x7fffc8bf8ca0 remoteAddr=0x7fffc8bf8d30 fd=4 errfd=-1 pid=0
2015-11-13 18:11:29.660+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603830 classname=virNetSocket
2015-11-13 18:11:29.660+0000: 3945: info : virNetSocketNew:276 : RPC_SOCKET_NEW: sock=0x2603830 fd=4 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2015-11-13 18:11:29.660+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603670 classname=virNetClient
2015-11-13 18:11:29.660+0000: 3945: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x2603670 sock=0x2603830
2015-11-13 18:11:29.660+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603670
2015-11-13 18:11:29.660+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603830
2015-11-13 18:11:29.660+0000: 3945: debug : virNetSocketAddIOCallback:1955 : Failed to register watch on socket 0x2603830
2015-11-13 18:11:29.660+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603830
2015-11-13 18:11:29.660+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603670
2015-11-13 18:11:29.660+0000: 3945: debug : doRemoteOpen:972 : Failed to add event watch, disabling events and support for keepalive messages
2015-11-13 18:11:29.660+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x25d8060
2015-11-13 18:11:29.661+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603b50 classname=virNetClientProgram
2015-11-13 18:11:29.661+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603c30 classname=virNetClientProgram
2015-11-13 18:11:29.661+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603ca0 classname=virNetClientProgram
2015-11-13 18:11:29.661+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603b50
2015-11-13 18:11:29.661+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603c30
2015-11-13 18:11:29.661+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603ca0
2015-11-13 18:11:29.661+0000: 3945: debug : doRemoteOpen:1010 : Trying authentication
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603f40 tracked=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.661+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603f40, expectReply=1, nonBlock=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.661+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 36 total (32 more)
2015-11-13 18:11:29.661+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=36 prog=536903814 vers=1 proc=66 type=1 status=0 serial=0
2015-11-13 18:11:29.661+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.661+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603f40 nfds=0 cb=(nil)
2015-11-13 18:11:29.661+0000: 3945: debug : doRemoteOpen:1036 : Trying to open URI 
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageNew:46 : msg=0x26024c0 tracked=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 40
2015-11-13 18:11:29.661+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=40 prog=536903814 vers=1 proc=1 type=0 status=0 serial=1
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x26024c0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=1 proc=1 type=0 length=40 dispatch=(nil)
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.661+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.661+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=1
2015-11-13 18:11:29.661+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.661+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageFree:74 : msg=0x26024c0 nfds=0 cb=(nil)
2015-11-13 18:11:29.661+0000: 3945: debug : doRemoteOpen:1047 : Trying to query remote URI
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603a00 tracked=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.661+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=110 type=0 status=0 serial=2
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603a00, expectReply=1, nonBlock=0
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=2 proc=110 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.661+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.661+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.662+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 48 total (44 more)
2015-11-13 18:11:29.662+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=48 prog=536903814 vers=1 proc=110 type=1 status=0 serial=2
2015-11-13 18:11:29.662+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.662+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.662+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.672+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603a00 nfds=0 cb=(nil)
2015-11-13 18:11:29.672+0000: 3945: debug : doRemoteOpen:1055 : Auto-probed URI is qemu:///system
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603a70 tracked=0
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 32
2015-11-13 18:11:29.672+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=3
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603a70, expectReply=1, nonBlock=0
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=3 proc=60 type=0 length=32 dispatch=(nil)
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.672+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 32 total (28 more)
2015-11-13 18:11:29.672+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=3
2015-11-13 18:11:29.672+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.672+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.672+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.672+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603a70 nfds=0 cb=(nil)
2015-11-13 18:11:29.672+0000: 3945: debug : do_open:1194 : driver 2 remote returned SUCCESS
2015-11-13 18:11:29.672+0000: 3945: debug : virDomainLookupByName:416 : conn=0x25ed280, name=conversion-test-vm (43f00f9c-276b-4bc7-9c2f-66c41824960e)
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageNew:46 : msg=0x2601b50 tracked=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 92
2015-11-13 18:11:29.673+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=92 prog=536903814 vers=1 proc=23 type=0 status=0 serial=4
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x2601b50, expectReply=1, nonBlock=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=4 proc=23 type=0 length=92 dispatch=(nil)
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 300 total (296 more)
2015-11-13 18:11:29.673+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=300 prog=536903814 vers=1 proc=23 type=1 status=1 serial=4
2015-11-13 18:11:29.673+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.673+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageFree:74 : msg=0x2601b50 nfds=0 cb=(nil)
2015-11-13 18:11:29.673+0000: 3945: debug : virConnectClose:1384 : conn=0x25ed280
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25ed280
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25ed280
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageNew:46 : msg=0x2602450 tracked=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.673+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=5
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25ed4c0: msg=0x2602450, expectReply=1, nonBlock=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=5 proc=2 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25ed4c0 call=0x25ed4c0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.673+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=28 prog=536903814 vers=1 proc=2 type=1 status=0 serial=5
2015-11-13 18:11:29.673+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25ed4c0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.673+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25ed4c0 rv=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetMessageFree:74 : msg=0x2602450 nfds=0 cb=(nil)
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientCloseInternal:695 : client=0x2603670 wantclose=0
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientMarkClose:638 : client=0x2603670, reason=3
2015-11-13 18:11:29.673+0000: 3945: debug : virNetSocketRemoveIOCallback:1991 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck (nil)
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.673+0000: 3945: debug : virNetClientCloseLocked:654 : client=0x2603670, sock=0x2603830, reason=3
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603830
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603830
2015-11-13 18:11:29.673+0000: 3945: info : virNetSocketDispose:1155 : RPC_SOCKET_DISPOSE: sock=0x2603830
2015-11-13 18:11:29.673+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603670
2015-11-13 18:11:29.673+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603670
2015-11-13 18:11:29.699+0000: 3945: info : virNetClientDispose:606 : RPC_CLIENT_DISPOSE: client=0x2603670
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603b50
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603c30
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603ca0
2015-11-13 18:11:29.699+0000: 3945: debug : virFileClose:102 : Closed fd 10
2015-11-13 18:11:29.699+0000: 3945: debug : virFileClose:102 : Closed fd 9
2015-11-13 18:11:29.699+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603b50
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603b50
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603c30
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603c30
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603ca0
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603ca0
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.699+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25d8060
2015-11-13 18:11:29.699+0000: 3945: debug : virConnectOpenAuth:1339 : name=<null>, auth=0x7fbbac7e73e0, flags=1
2015-11-13 18:11:29.699+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25ed280 classname=virConnect
2015-11-13 18:11:29.699+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x25d8060 classname=virConnectCloseCallbackData
2015-11-13 18:11:29.699+0000: 3945: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf'
2015-11-13 18:11:29.699+0000: 3945: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf
2015-11-13 18:11:29.699+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1136 : no name, allowing driver auto-select
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1179 : trying driver 0 (Test) ...
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1194 : driver 0 Test returned DECLINED
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1179 : trying driver 1 (ESX) ...
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1194 : driver 1 ESX returned DECLINED
2015-11-13 18:11:29.699+0000: 3945: debug : do_open:1179 : trying driver 2 (remote) ...
2015-11-13 18:11:29.699+0000: 3945: debug : remoteConnectOpen:1191 : Auto-probe remote URI
2015-11-13 18:11:29.699+0000: 3945: debug : doRemoteOpen:792 : proceeding with name = 
2015-11-13 18:11:29.699+0000: 3945: debug : doRemoteOpen:801 : Connecting with transport 1
2015-11-13 18:11:29.699+0000: 3945: debug : doRemoteOpen:893 : Proceeding with sockname /var/run/libvirt/libvirt-sock-ro
2015-11-13 18:11:29.700+0000: 3945: debug : virNetSocketNew:225 : localAddr=0x7fffc8bf8ab0 remoteAddr=0x7fffc8bf8b40 fd=4 errfd=-1 pid=0
2015-11-13 18:11:29.700+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603830 classname=virNetSocket
2015-11-13 18:11:29.700+0000: 3945: info : virNetSocketNew:276 : RPC_SOCKET_NEW: sock=0x2603830 fd=4 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
2015-11-13 18:11:29.700+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603670 classname=virNetClient
2015-11-13 18:11:29.700+0000: 3945: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x2603670 sock=0x2603830
2015-11-13 18:11:29.700+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603670
2015-11-13 18:11:29.700+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603830
2015-11-13 18:11:29.700+0000: 3945: debug : virNetSocketAddIOCallback:1955 : Failed to register watch on socket 0x2603830
2015-11-13 18:11:29.700+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603830
2015-11-13 18:11:29.700+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603670
2015-11-13 18:11:29.700+0000: 3945: debug : doRemoteOpen:972 : Failed to add event watch, disabling events and support for keepalive messages
2015-11-13 18:11:29.700+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x25d8060
2015-11-13 18:11:29.700+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603b50 classname=virNetClientProgram
2015-11-13 18:11:29.700+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603c30 classname=virNetClientProgram
2015-11-13 18:11:29.705+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2603ca0 classname=virNetClientProgram
2015-11-13 18:11:29.705+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603b50
2015-11-13 18:11:29.705+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603c30
2015-11-13 18:11:29.705+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x2603ca0
2015-11-13 18:11:29.705+0000: 3945: debug : doRemoteOpen:1010 : Trying authentication
2015-11-13 18:11:29.705+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603f40 tracked=0
2015-11-13 18:11:29.705+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.705+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0
2015-11-13 18:11:29.705+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603f40, expectReply=1, nonBlock=0
2015-11-13 18:11:29.705+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.705+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.705+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 36 total (32 more)
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=36 prog=536903814 vers=1 proc=66 type=1 status=0 serial=0
2015-11-13 18:11:29.706+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603f40 nfds=0 cb=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : doRemoteOpen:1036 : Trying to open URI 
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageNew:46 : msg=0x26024c0 tracked=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 40
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=40 prog=536903814 vers=1 proc=1 type=0 status=0 serial=1
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x26024c0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=1 proc=1 type=0 length=40 dispatch=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=28 prog=536903814 vers=1 proc=1 type=1 status=0 serial=1
2015-11-13 18:11:29.706+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageFree:74 : msg=0x26024c0 nfds=0 cb=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : doRemoteOpen:1047 : Trying to query remote URI
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603a00 tracked=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=110 type=0 status=0 serial=2
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603a00, expectReply=1, nonBlock=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=2 proc=110 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 48 total (44 more)
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=48 prog=536903814 vers=1 proc=110 type=1 status=0 serial=2
2015-11-13 18:11:29.706+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603a00 nfds=0 cb=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : doRemoteOpen:1055 : Auto-probed URI is qemu:///system
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603a70 tracked=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 32
2015-11-13 18:11:29.706+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=32 prog=536903814 vers=1 proc=60 type=0 status=0 serial=3
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25d6b30: msg=0x2603a70, expectReply=1, nonBlock=0
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=3 proc=60 type=0 length=32 dispatch=(nil)
2015-11-13 18:11:29.706+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25d6b30 call=0x25d6b30
2015-11-13 18:11:29.706+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.706+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 32 total (28 more)
2015-11-13 18:11:29.707+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=32 prog=536903814 vers=1 proc=60 type=1 status=0 serial=3
2015-11-13 18:11:29.707+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.707+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25d6b30
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.707+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25d6b30 rv=0
2015-11-13 18:11:29.707+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603a70 nfds=0 cb=(nil)
2015-11-13 18:11:29.707+0000: 3945: debug : do_open:1194 : driver 2 remote returned SUCCESS
2015-11-13 18:11:29.707+0000: 3945: debug : virStoragePoolLookupByUUIDString:446 : conn=0x25ed280, uuidstr=virtimages
2015-11-13 18:11:29.707+0000: 3945: debug : virStoragePoolLookupByName:367 : conn=0x25ed280, name=virtimages
2015-11-13 18:11:29.707+0000: 3945: debug : virNetMessageNew:46 : msg=0x2601bc0 tracked=0
2015-11-13 18:11:29.707+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 44
2015-11-13 18:11:29.707+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=44 prog=536903814 vers=1 proc=84 type=0 status=0 serial=4
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25ed4c0: msg=0x2601bc0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=4 proc=84 type=0 length=44 dispatch=(nil)
2015-11-13 18:11:29.707+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25ed4c0 call=0x25ed4c0
2015-11-13 18:11:29.707+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.707+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 60 total (56 more)
2015-11-13 18:11:29.728+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=60 prog=536903814 vers=1 proc=84 type=1 status=0 serial=4
2015-11-13 18:11:29.728+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.728+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25ed4c0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.728+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25ed4c0 rv=0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetMessageFree:74 : msg=0x2601bc0 nfds=0 cb=(nil)
2015-11-13 18:11:29.728+0000: 3945: info : virObjectNew:202 : OBJECT_NEW: obj=0x2601ae0 classname=virStoragePool
2015-11-13 18:11:29.728+0000: 3945: info : virObjectRef:296 : OBJECT_REF: obj=0x25ed280
2015-11-13 18:11:29.728+0000: 3945: debug : virStoragePoolGetConnect:48 : pool=0x2601ae0
2015-11-13 18:11:29.728+0000: 3945: debug : virStoragePoolGetXMLDesc:1026 : pool=0x2601ae0, flags=0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetMessageNew:46 : msg=0x2603ce0 tracked=0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 64
2015-11-13 18:11:29.728+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=64 prog=536903814 vers=1 proc=88 type=0 status=0 serial=5
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25eccc0: msg=0x2603ce0, expectReply=1, nonBlock=0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=5 proc=88 type=0 length=64 dispatch=(nil)
2015-11-13 18:11:29.728+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25eccc0 call=0x25eccc0
2015-11-13 18:11:29.728+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.729+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 520 total (516 more)
2015-11-13 18:11:29.729+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=520 prog=536903814 vers=1 proc=88 type=1 status=0 serial=5
2015-11-13 18:11:29.729+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.729+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.729+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25eccc0
2015-11-13 18:11:29.729+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.729+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.729+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25eccc0 rv=0
2015-11-13 18:11:29.729+0000: 3945: debug : virNetMessageFree:74 : msg=0x2603ce0 nfds=0 cb=(nil)
2015-11-13 18:11:29.729+0000: 3945: debug : virStoragePoolFree:803 : pool=0x2601ae0
2015-11-13 18:11:29.729+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2601ae0
2015-11-13 18:11:29.729+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2601ae0
2015-11-13 18:11:29.729+0000: 3945: debug : virStoragePoolDispose:437 : release pool 0x2601ae0 virtimages 6ef8b618-166e-4a33-9c3b-7106328c9d73
2015-11-13 18:11:29.729+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25ed280
2015-11-13 18:11:29.729+0000: 3945: debug : virConnectClose:1384 : conn=0x25ed280
2015-11-13 18:11:29.729+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25ed280
2015-11-13 18:11:29.729+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25ed280
2015-11-13 18:11:29.735+0000: 3945: debug : virNetMessageNew:46 : msg=0x2604040 tracked=0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetMessageEncodePayload:376 : Encode length as 28
2015-11-13 18:11:29.735+0000: 3945: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x2603670 len=28 prog=536903814 vers=1 proc=2 type=0 status=0 serial=6
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientCallNew:1903 : New call 0x25ed4c0: msg=0x2604040, expectReply=1, nonBlock=0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=6 proc=2 type=0 length=28 dispatch=(nil)
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIO:1771 : We have the buck head=0x25ed4c0 call=0x25ed4c0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.735+0000: 3945: debug : virNetMessageDecodeLength:151 : Got length, now need 28 total (24 more)
2015-11-13 18:11:29.735+0000: 3945: info : virNetClientCallDispatch:1122 : RPC_CLIENT_MSG_RX: client=0x2603670 len=28 prog=536903814 vers=1 proc=2 type=1 status=0 serial=6
2015-11-13 18:11:29.735+0000: 3945: debug : virKeepAliveCheckMessage:377 : ka=(nil), client=0x7fbbac53ffa5, msg=0x26036d8
2015-11-13 18:11:29.735+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x25ed4c0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.735+0000: 3945: debug : virNetSocketUpdateIOCallback:1976 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x25ed4c0 rv=0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetMessageFree:74 : msg=0x2604040 nfds=0 cb=(nil)
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientCloseInternal:695 : client=0x2603670 wantclose=0
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientMarkClose:638 : client=0x2603670, reason=3
2015-11-13 18:11:29.735+0000: 3945: debug : virNetSocketRemoveIOCallback:1991 : Watch not registered on socket 0x2603830
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck (nil)
2015-11-13 18:11:29.735+0000: 3945: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to
2015-11-13 18:11:29.736+0000: 3945: debug : virNetClientCloseLocked:654 : client=0x2603670, sock=0x2603830, reason=3
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603830
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603830
2015-11-13 18:11:29.736+0000: 3945: info : virNetSocketDispose:1155 : RPC_SOCKET_DISPOSE: sock=0x2603830
2015-11-13 18:11:29.736+0000: 3945: debug : virFileClose:102 : Closed fd 4
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603670
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603670
2015-11-13 18:11:29.736+0000: 3945: info : virNetClientDispose:606 : RPC_CLIENT_DISPOSE: client=0x2603670
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603b50
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603c30
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603ca0
2015-11-13 18:11:29.736+0000: 3945: debug : virFileClose:102 : Closed fd 10
2015-11-13 18:11:29.736+0000: 3945: debug : virFileClose:102 : Closed fd 9
2015-11-13 18:11:29.736+0000: 3945: debug : virNetMessageClear:57 : msg=0x26036d8 nfds=0
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603b50
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603b50
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603c30
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603c30
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x2603ca0
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x2603ca0
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x25d8060
2015-11-13 18:11:29.736+0000: 3945: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x25d8060
[  23.3] Inspecting the overlay
[ 136.7] Checking for sufficient free disk space in the guest
[ 136.7] Estimating space required on target for each disk
[ 136.7] Converting Windows Server 2012 R2 Standard to run on KVM
virt-v2v: error: virt-v2v cannot be used to convert Windows > 7 / 2008R2 
(see https://bugzilla.redhat.com/1190669)

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

Comment 22 Richard W.M. Jones 2015-11-13 18:41:37 UTC

The patch for Windows > 7 is not included in the previews yet.
Please see comment 17.

Comment 23 Alessandro 2015-11-13 19:29:09 UTC

Thank you, Richard.
Is there a link where I can check when the patch and final version will be released?

Regards

Comment 24 Richard W.M. Jones 2015-11-13 21:49:19 UTC

Yes, this bug will be updated when a package is available.

Comment 25 Alessandro 2015-11-13 22:03:21 UTC

Thank you!

Comment 48 Richard W.M. Jones 2016-02-09 14:47:01 UTC

There is zero chance of this in 7.2.z.

Comment 49 Alessandro 2016-02-13 23:31:37 UTC

Any chance of Windows > 7 supported in version 7.3 any time soon?

Comment 50 Richard W.M. Jones 2016-02-14 11:01:54 UTC

Please try the preview packages which can perform Windows > 7
conversions.  They are not supported at the moment, and no final
decision has been made about RHEL 7.3.

https://people.redhat.com/~rjones/libguestfs-RHEL-7.3-preview/

Comment 53 tingting zheng 2016-02-17 09:07:58 UTC

For downstream build virt-v2v-1.32.2-3.el7.x86_64,in ovf file and rhevm GUI,the descrption field still shows something like:
generated by virt-v2v 1.32.2rhel=7,release=3.el7,libvirt

btw,QE are testing convert Windows > 7 using virt-v2v-1.32.2-3.el7.x86_64 and will add comments about the results later.

Comment 54 tingting zheng 2016-02-18 10:21:28 UTC

Hi,Richard

I saw fix of this bug has already in virt-v2v-1.32.2-3.el7.x86_64,need it be added in erratum?

Comment 55 Richard W.M. Jones 2016-02-18 10:30:22 UTC

Yes, I will add it shortly.

Comment 56 Richard W.M. Jones 2016-02-18 10:32:31 UTC

Erm, NO, actually.  I'm not dev-acking this bug until it has
received much more testing.

Comment 57 mxie@redhat.com 2016-02-23 09:29:00 UTC

Tested with:
libguestfs-1.32.2-6.el7.x86_64
virt-v2v-1.32.2-6.el7.x86_64
virtio-win-1.8.0-4.el7.noarch
libguestfs-winsupport-7.1-4.el7.x86_64

Test conversion win8,win8.1,win2012,win2012R2,win10 from xen/esx.

win8 from xen:
# virt-v2v -ic xen+ssh://10.66.106.64 -b virbr0  xen-hvm-win8-i386  -of qcow2
# virt-v2v -ic xen+ssh://10.66.106.64 -b virbr0  xen-hvm-win8-x86_64  -of qcow2

win8.1x86,win10x86 from esx5.5:
# virt-v2v -ic vpx://root.4.103/tzheng-demo/10.66.106.63/?no_verify=1 -b virbr0 esx5.5-win8.1-i386 -of raw --password-file /tmp/passwd
# virt-v2v -ic vpx://root.4.103/tzheng-demo/10.66.106.63/?no_verify=1 -b virbr0 esx5.5-win10-i386 -of raw --password-file /tmp/passwd -o rhev -os 10.73.69.63:/home/nfs_export -b virtmgmt -b virtmgmt 

win8.1x64,win2012 from esx6.0:
# virt-v2v -ic vpx://root.145.47/data/10.66.144.40/?no_verify=1 -b virbr0 esx6.0-win2012-x86_64 -of raw --password-file /tmp/passwd 
# virt-v2v -ic vpx://root.145.47/data/10.66.144.40/?no_verify=1 -b virbr0 esx6.0-win8.1-x86_64 -of raw --password-file /tmp/passwd 
 
win2012R2, win10x64 from esx5.1:
# virt-v2v -ic vpx://root.4.103/tzheng-demo/10.66.4.153/?no_verify=1 -b virbr0 esx5.1-win2012r2-x86_64 -of raw --password-file /tmp/passwd
# virt-v2v -ic vpx://root.4.103/tzheng-demo/10.66.4.153/?no_verify=1 -b virbr0 esx5.1-win10-x86_64 -of raw --password-file /tmp/passwd -o rhev -os 10.73.69.63:/home/nfs_export -b virtmgmt -b virtmgmt 

All the above guests can be converted successfully and guests can be booted successfully.But boot into win10 guest need hardware cpu>=Intel sandybrige Family and win8 guest need hardware cpu >=Intel Penryn Family

Comment 58 mxie@redhat.com 2016-02-23 10:18:34 UTC

Sorry forget to modify libguestfs-winsupport version at comment57, correct as libguestfs-winsupport-7.2-1.el7.x86_64

Comment 67 Vladimir 2016-08-17 22:40:24 UTC

Hi Richard,

I've reviewed your commit https://github.com/libguestfs/libguestfs/commit/2817824bd34e30fe6a2eeb65105067bd058f1fac 

As far as I see you use pre-calculated hash c86329aaeb0a7904 to add virtio driver to DriverStore. 
The method works for one Windows driver version only - one that hash sum is calculated for. 
The hash calculation based on *.inf file that is subject to change over VirtIo versions. It implies Windows won't convert with the newer driver versions (if inf's are changed).

Based on Windows libraries disassembly I've got an algorithm to calculate the hash for arbitrary driver *.inf. 

I'll gladly share the know-how with the community. What is the way to contribute \ suggest a patch?

Thanks ;)

Comment 68 Richard W.M. Jones 2016-08-18 07:53:15 UTC

Patches can be emailed to libguestfs <at> redhat.com.  There is
no need to subscribe to the list if you don't want to.

Comment 69 mxie@redhat.com 2016-09-08 03:00:50 UTC

According to the result of full matrix, there is no critical regression/block bug found. So move this bug from ON_QA to VERIFIED

Comment 71 Richard W.M. Jones 2016-09-09 16:47:08 UTC

https://people.redhat.com/~rjones/libguestfs-RHEL-7.3-preview/
http://oirase.annexia.org/virt-p2v/

Comment 81 errata-xmlrpc 2016-11-03 17:49:28 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2016-2576.html