Re: [ovirt-users] Importing VM from Xen Server 6.5

Hi, I have attached the log of both virsh -c ssh://root@192.168.1.40 & virsh -c xen+ssh://root@192.168.1.40 Hope this helps to debug.

-- Thanks & Regards, Anantha Raghava Do not print this e-mail unless required. Save Paper & trees. On Thursday 11 August 2016 04:01 PM, Shahar Havivi wrote: > On 11.08.16 14:14, Anantha Raghava wrote: > > Hi, > > > > Tested this with different combinations: > > > > a. from VDSM host, both "ssh root(a)192.168.1.40&quot; and "sudo -u vdsm ssh > > root(a)192.168.1.40&quot; commands are logging in without asking for password and I > > can run all xe commands without any glitch without modifications to default > > xen server firewall or SELinux rules. > > > > b. With firewall enabled and SELinux set to enforcing or permissive or > > disabled, I run "virsh -c ssh://root@192.168.1.40". And the command is > > resulting in two errors: > > > > error: filed to connect to the hypervisor > > error: unable to connect to the server at '192.168.1.40:16514' : No > > route to the host. > > > > c. With firewall disabled and SELinux set to Enforcing or permissive or > > disabled, I run "virsh -c ssh://192.168.1.40". And the command is resulting > > in two errors > > > > error: filed to connect to the hypervisor > > error: unable to connect to the server at '192.168.1.40:16514' : > > Connection refused > Good tests, > We need to figure out why libvirt refuse the connection, > try to debug virsh by running: > > $ export LIBVIRT_LOG_OUTPUTS="1:file:/tmp/libvirt_client.log" > $ export LIBVIRT_DEBUG=1 > $ virsh -c virsh -c ssh://192.168.1.40 > > and examing /tmp/libvirt_client.log file > > > -- > > > > Thanks & Regards, > > > > > > Anantha Raghava > > > > eXza Technology Consulting & Services > > > > Ph: +91-9538849179, E-mail: raghav(a)exzatechconsulting.com > > <mailto:raghav@exzatechconsulting.com> > > > > URL: http://www.exzatechconsulting.com <http://www.exzatechconsulting.com/> > > > > /*Support No.: +91-7829774584 */ > > > > > > > > DISCLAIMER: > > This e-mail communication and any attachments may be privileged and > > confidential to eXza Technology Consulting & Services, and are intended only > > for the use of the recipients named above If you are not the addressee you > > may not copy, forward, disclose or use any part of it. If you have received > > this message in error, please delete it and all copies from your system and > > notify the sender immediately by return e-mail. Internet communications > > cannot be guaranteed to be timely, secure, error or virus-free. The sender > > does not accept liability for any errors or omissions. > > > > > > Do not print this e-mail unless required. Save Paper & trees. > > > > On Thursday 11 August 2016 12:20 PM, Shahar Havivi wrote: > > > On 10.08.16 19:40, Anantha Raghava wrote: > > > > Hello Richard / Shahar, > > > > > > > > I installed and enabled nc on Xen Server host. Now the " ...... sh: nc: > > > > command not found: Input/output error" is gone. Communication is > > > > established. However I am still getting two specific errors: > > > > > > > > VDSM ovirt_engine command failed: End of file while reading data: : > > > > Input/Output error > > > > > > > > & > > > > > > > > Failed to retrieve VMs Information from the external server > > > > xen+ssh://root@192.168.1.40 > > > > > > > > I am receiving the same error when I run virsh -c > > > > xen+ssh://root@192.168.1.40 > > > > > > > > Screen shot is attached for quick reference. > > > > > > > > Is it something to do with firewall / ip tables on xen server or libvirtd > > > > host? > > > Hi, > > > You don't need to try it on oVirt when 'virsh -c' doesn't work since oVirt try > > > to connect via libvirt libraries (same as virsh) before it called virt-v2v. > > > > > > Did you follow all the steps in the wiki? > > > Are you able to ssh to the Xen server from the vdsm machine that you try to > > > run virsh without password? (ssh root(a)192.168.1.40) > > > > > > > -- > > > > > > > > Thanks & Regards, > > > > > > > > Anantha Raghava > > > > > > > > > > > > Do not print this e-mail unless required. Save Paper & trees. > > > > > > > > On Wednesday 10 August 2016 06:04 PM, Anantha Raghava wrote: > > > > > Hi, > > > > > > > > > > Let me try this and post the results here. > > > > > > > > > > Regards, > > > > > Ananth > > > > > > > > > > On 10 Aug 2016 15:28, "Richard W.M. Jones" <rjones(a)redhat.com > > > > > <mailto:rjones@redhat.com>> wrote: > > > > > > > > > > On Wed, Aug 10, 2016 at 09:45:52AM +0300, Shahar Havivi wrote: > > > > > > On 10.08.16 06:45, Anantha Raghava wrote: > > > > > > > Hi, > > > > > > > > > > > > > > I even attempted to run command virsh -c > > > > > xen+ssh://root@xenhost and I get > > > > > > > error "/*error: End of file reading data: sh: nc: command not > > > > > found: > > > > > > > Input/output error"*/ > > > > > > First you need to be able to login via virsh (before trying to > > > > > import via > > > > > > oVirt). > > > > > > > > > > > > I never encounter this error before, > > > > > > I guess that nc is netcat..., > > > > > > try to install nmap-ncat: > > > > > > $ dnf info nmap-ncat > > > > > > > > > > > > Adding Richard which may have more input. > > > > > > > > > > Yes, you need to install 'nc' on the *target* (Xen) machine. > > > > > > > > > > This is because libvirt's ssh transport uses nc: > > > > > https://libvirt.org/guide/html/Application_Development_Guide-Architecture... > > > > > <https://libvirt.org/guide/html/Application_Development_Guide-Architecture... > > > > > > > > > > Rich. > > > > > > > > > > -- > > > > > Richard Jones, Virtualization Group, Red Hat > > > > > http://people.redhat.com/~rjones <http://people.redhat.com/%7Erjones> > > > > > Read my programming and virtualization blog: http://rwmj.wordpress.com > > > > > virt-builder quickly builds VMs from scratch > > > > > http://libguestfs.org/virt-builder.1.html > > > > > <http://libguestfs.org/virt-builder.1.html> > > > > >

------ from here you can see the debug log of command virsh -c ssh://root@192.168.1.40 --------- 2016-08-11 12:15:24.011+0000: 43283: info : libvirt version: 1.2.17, package: 13.el7_2.5 (CentOS BuildSystem <http://bugs.centos.org>;, 2016-06-23-14:23:27, worker1.bsys.centos.org) 2016-08-11 12:15:24.011+0000: 43283: debug : virGlobalInit:389 : register drivers 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:691 : driver=0x7f975826a640 name=Test 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:702 : registering Test as driver 0 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:691 : driver=0x7f975826c260 name=ESX 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:702 : registering ESX as driver 1 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:691 : driver=0x7f975826b0c0 name=remote 2016-08-11 12:15:24.011+0000: 43283: debug : virRegisterConnectDriver:702 : registering remote as driver 2 2016-08-11 12:15:24.011+0000: 43283: debug : virEventRegisterDefaultImpl:261 : registering default event implementation 2016-08-11 12:15:24.011+0000: 43283: debug : virEventPollAddHandle:115 : Used 0 handle slots, adding at least 10 more 2016-08-11 12:15:24.011+0000: 43283: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 0 2016-08-11 12:15:24.011+0000: 43283: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=5 events=1 cb=0x7f9757da9920 opaque=(nil) ff=(nil) 2016-08-11 12:15:24.011+0000: 43283: debug : virEventRegisterImpl:231 : addHandle=0x7f9757daa080 updateHandle=0x7f9757daa3e0 removeHandle=0x7f9757da9980 addTimeout=0x7f9757da9b00 updateTimeout=0x7f9757da9d20 removeTimeout=0x7f9757da9ef0 2016-08-11 12:15:24.011+0000: 43283: debug : virEventPollAddTimeout:230 : Used 0 timeout slots, adding at least 10 more 2016-08-11 12:15:24.011+0000: 43283: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 0 2016-08-11 12:15:24.011+0000: 43283: info : virEventPollAddTimeout:253 : EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=-1 cb=0x7f97584b7c10 opaque=0x7ffe0aa3bc30 ff=(nil) 2016-08-11 12:15:24.011+0000: 43283: debug : virConnectOpenAuth:1339 : name=ssh://root@192.168.1.40, auth=0x7f975826a400, flags=0 2016-08-11 12:15:24.011+0000: 43283: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f97587985e0 classname=virConnect 2016-08-11 12:15:24.011+0000: 43283: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9758797f20 classname=virConnectCloseCallbackData 2016-08-11 12:15:24.011+0000: 43283: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf' 2016-08-11 12:15:24.011+0000: 43283: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf 2016-08-11 12:15:24.011+0000: 43284: debug : virThreadJobSet:99 : Thread 43284 is now running job vshEventLoop 2016-08-11 12:15:24.011+0000: 43283: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:15:24.011+0000: 43284: debug : virEventRunDefaultImpl:305 : running default event implementation 2016-08-11 12:15:24.011+0000: 43284: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:15:24.011+0000: 43284: debug : virEventPollCleanupHandles:575 : Cleanup 1 2016-08-11 12:15:24.011+0000: 43284: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2016-08-11 12:15:24.011+0000: 43284: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers 2016-08-11 12:15:24.011+0000: 43284: debug : virEventPollCalculateTimeout:371 : No timeout is pending 2016-08-11 12:15:24.011+0000: 43284: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1132 : name "ssh://root@192.168.1.40" to URI components: scheme ssh server 192.168.1.40 user root port 0 path <null> 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1179 : trying driver 0 (Test) ... 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1194 : driver 0 Test returned DECLINED 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1179 : trying driver 1 (ESX) ... 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1194 : driver 1 ESX returned DECLINED 2016-08-11 12:15:24.011+0000: 43283: debug : do_open:1179 : trying driver 2 (remote) ... 2016-08-11 12:15:24.011+0000: 43283: debug : doRemoteOpen:792 : proceeding with name = ssh:// 2016-08-11 12:15:24.011+0000: 43283: debug : doRemoteOpen:801 : Connecting with transport 0 2016-08-11 12:15:24.011+0000: 43283: debug : virNetTLSContextLocateCredentials:813 : pkipath=(null) isServer=0 tryUserPkiPath=0 2016-08-11 12:15:24.011+0000: 43283: debug : virNetTLSContextLocateCredentials:885 : Using default TLS CA certificate path 2016-08-11 12:15:24.011+0000: 43283: debug : virNetTLSContextLocateCredentials:891 : Using default TLS CA revocation list path 2016-08-11 12:15:24.011+0000: 43283: debug : virNetTLSContextLocateCredentials:897 : Using default TLS key/certificate path 2016-08-11 12:15:24.011+0000: 43283: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f975879a9c0 classname=virNetTLSContext 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextLoadCertFromFile:516 : isServer 0 certFile /etc/pki/libvirt/clientcert.pem 2016-08-11 12:15:24.012+0000: 43283: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextLoadCACertListFromFile:560 : certFile /etc/pki/CA/cacert.pem 2016-08-11 12:15:24.012+0000: 43283: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertBasicConstraints:189 : Cert /etc/pki/libvirt/clientcert.pem basic constraints 0 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertKeyUsage:235 : Cert /etc/pki/libvirt/clientcert.pem key usage status 0 usage 160 critical 1 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertKeyPurpose:335 : Key purpose 0 1.3.6.1.5.5.7.3.1 critical 1 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertKeyPurpose:335 : Key purpose 0 1.3.6.1.5.5.7.3.2 critical 1 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertKeyPurpose:307 : No key purpose data available at slot 2 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertBasicConstraints:189 : Cert /etc/pki/CA/cacert.pem basic constraints 1 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextCheckCertKeyUsage:235 : Cert /etc/pki/CA/cacert.pem key usage status 0 usage 6 critical 1 2016-08-11 12:15:24.012+0000: 43283: debug : virNetTLSContextLoadCredentials:642 : loading CA cert from /etc/pki/CA/cacert.pem 2016-08-11 12:15:24.013+0000: 43283: debug : virNetTLSContextLoadCredentials:671 : Skipping non-existent CA CRL /etc/pki/CA/cacrl.pem 2016-08-11 12:15:24.013+0000: 43283: debug : virNetTLSContextLoadCredentials:684 : loading cert and key from /etc/pki/libvirt/clientcert.pem and /etc/pki/libvirt/private/clientkey.pem 2016-08-11 12:15:24.014+0000: 43283: info : virNetTLSContextNew:783 : RPC_TLS_CONTEXT_NEW: ctxt=0x7f975879a9c0 cacert=/etc/pki/CA/cacert.pem cacrl=/etc/pki/CA/cacrl.pem cert=/etc/pki/libvirt/clientcert.pem key=/etc/pki/libvirt/private/clientkey.pem sanityCheckCert=1 requireValidCert=1 isServer=0 2016-08-11 12:15:24.016+0000: 43283: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:15:24.016+0000: 43283: error : virNetSocketNewConnectTCP:577 : unable to connect to server at '192.168.1.40:16514': Connection refused 2016-08-11 12:15:24.016+0000: 43283: debug : virNetClientCloseInternal:695 : client=(nil) wantclose=0 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f975879a9c0 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f975879a9c0 2016-08-11 12:15:24.016+0000: 43283: info : virNetTLSContextDispose:1169 : RPC_TLS_CONTEXT_DISPOSE: ctxt=0x7f975879a9c0 2016-08-11 12:15:24.016+0000: 43283: debug : do_open:1194 : driver 2 remote returned ERROR 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f97587985e0 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f97587985e0 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9758797f20 2016-08-11 12:15:24.016+0000: 43283: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9758797f20 2016-08-11 12:15:24.016+0000: 43283: debug : virEventPollInterruptLocked:727 : Interrupting 2016-08-11 12:15:24.016+0000: 43283: info : virEventPollAddTimeout:253 : EVENT_POLL_ADD_TIMEOUT: timer=2 frequency=0 cb=0x7f97584b7ae0 opaque=(nil) ff=(nil) 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollRunOnce:651 : Poll got 1 event(s) 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollDispatchTimeouts:433 : Dispatch 2 2016-08-11 12:15:24.016+0000: 43284: info : virEventPollDispatchTimeouts:456 : EVENT_POLL_DISPATCH_TIMEOUT: timer=2 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollDispatchHandles:479 : Dispatch 1 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollDispatchHandles:493 : i=0 w=1 2016-08-11 12:15:24.016+0000: 43284: info : virEventPollDispatchHandles:507 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollCleanupTimeouts:526 : Cleanup 2 2016-08-11 12:15:24.016+0000: 43284: debug : virEventPollCleanupHandles:575 : Cleanup 1 2016-08-11 12:15:24.016+0000: 43284: debug : virThreadJobClear:124 : Thread 43284 finished job vshEventLoop with ret=0 2016-08-11 12:15:24.016+0000: 43283: info : virEventPollRemoveTimeout:305 : EVENT_POLL_REMOVE_TIMEOUT: timer=2 2016-08-11 12:15:24.016+0000: 43283: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 140287726221056 2016-08-11 12:15:24.016+0000: 43283: info : virEventPollRemoveTimeout:305 : EVENT_POLL_REMOVE_TIMEOUT: timer=1 2016-08-11 12:15:24.016+0000: 43283: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 140287726221056 -------- from here you can see debug log of command virsh -c xen+ssh://root@192.168.1.40 ----------- 2016-08-11 12:17:34.366+0000: 43669: info : libvirt version: 1.2.17, package: 13.el7_2.5 (CentOS BuildSystem <http://bugs.centos.org>;, 2016-06-23-14:23:27, worker1.bsys.centos.org) 2016-08-11 12:17:34.366+0000: 43669: debug : virGlobalInit:389 : register drivers 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:691 : driver=0x7f9661e6a640 name=Test 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:702 : registering Test as driver 0 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:691 : driver=0x7f9661e6c260 name=ESX 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:702 : registering ESX as driver 1 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:691 : driver=0x7f9661e6b0c0 name=remote 2016-08-11 12:17:34.367+0000: 43669: debug : virRegisterConnectDriver:702 : registering remote as driver 2 2016-08-11 12:17:34.367+0000: 43669: debug : virEventRegisterDefaultImpl:261 : registering default event implementation 2016-08-11 12:17:34.367+0000: 43669: debug : virEventPollAddHandle:115 : Used 0 handle slots, adding at least 10 more 2016-08-11 12:17:34.367+0000: 43669: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 0 2016-08-11 12:17:34.367+0000: 43669: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=5 events=1 cb=0x7f96619a9920 opaque=(nil) ff=(nil) 2016-08-11 12:17:34.367+0000: 43669: debug : virEventRegisterImpl:231 : addHandle=0x7f96619aa080 updateHandle=0x7f96619aa3e0 removeHandle=0x7f96619a9980 addTimeout=0x7f96619a9b00 updateTimeout=0x7f96619a9d20 removeTimeout=0x7f96619a9ef0 2016-08-11 12:17:34.367+0000: 43669: debug : virEventPollAddTimeout:230 : Used 0 timeout slots, adding at least 10 more 2016-08-11 12:17:34.367+0000: 43669: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 0 2016-08-11 12:17:34.367+0000: 43669: info : virEventPollAddTimeout:253 : EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=-1 cb=0x7f96620b7c10 opaque=0x7ffef5e35180 ff=(nil) 2016-08-11 12:17:34.367+0000: 43669: debug : virConnectOpenAuth:1339 : name=xen+ssh://root@192.168.1.40, auth=0x7f9661e6a400, flags=0 2016-08-11 12:17:34.367+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663423ec0 classname=virConnect 2016-08-11 12:17:34.367+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663421f20 classname=virConnectCloseCallbackData 2016-08-11 12:17:34.367+0000: 43670: debug : virThreadJobSet:99 : Thread 43670 is now running job vshEventLoop 2016-08-11 12:17:34.367+0000: 43670: debug : virEventRunDefaultImpl:305 : running default event implementation 2016-08-11 12:17:34.367+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.367+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 1 2016-08-11 12:17:34.367+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2016-08-11 12:17:34.367+0000: 43669: debug : virConnectGetConfigFile:953 : Loading config file '/etc/libvirt/libvirt.conf' 2016-08-11 12:17:34.367+0000: 43670: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers 2016-08-11 12:17:34.367+0000: 43670: debug : virEventPollCalculateTimeout:371 : No timeout is pending 2016-08-11 12:17:34.367+0000: 43669: debug : virConfReadFile:769 : filename=/etc/libvirt/libvirt.conf 2016-08-11 12:17:34.367+0000: 43670: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2016-08-11 12:17:34.367+0000: 43669: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1132 : name "xen+ssh://root@192.168.1.40" to URI components: scheme xen+ssh server 192.168.1.40 user root port 0 path <null> 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1179 : trying driver 0 (Test) ... 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1194 : driver 0 Test returned DECLINED 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1179 : trying driver 1 (ESX) ... 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1194 : driver 1 ESX returned DECLINED 2016-08-11 12:17:34.367+0000: 43669: debug : do_open:1179 : trying driver 2 (remote) ... 2016-08-11 12:17:34.367+0000: 43669: debug : doRemoteOpen:792 : proceeding with name = xen:// 2016-08-11 12:17:34.367+0000: 43669: debug : doRemoteOpen:801 : Connecting with transport 2 2016-08-11 12:17:34.368+0000: 43669: debug : virCommandRunAsync:2428 : About to run LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin HOME=/root USER=root LOGNAME=root ssh -l root 192.168.1.40 sh -c ''\''if '\''nc'\'' -q 2>&1 | grep "requires an argument" >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'\''nc'\'' $ARG -U /var/run/libvirt/libvirt-sock'\''' 2016-08-11 12:17:34.368+0000: 43669: debug : virCommandRunAsync:2431 : Command result 0, with PID 43671 2016-08-11 12:17:34.368+0000: 43669: debug : virFileClose:102 : Closed fd 8 2016-08-11 12:17:34.368+0000: 43669: debug : virFileClose:102 : Closed fd 10 2016-08-11 12:17:34.368+0000: 43669: debug : virNetSocketNew:225 : localAddr=(nil) remoteAddr=(nil) fd=7 errfd=9 pid=43671 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663424d90 classname=virNetSocket 2016-08-11 12:17:34.368+0000: 43669: info : virNetSocketNew:276 : RPC_SOCKET_NEW: sock=0x7f9663424d90 fd=7 errfd=9 pid=43671 localAddr=<null>, remoteAddr=<null> 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663424fd0 classname=virNetClient 2016-08-11 12:17:34.368+0000: 43669: info : virNetClientNew:327 : RPC_CLIENT_NEW: client=0x7f9663424fd0 sock=0x7f9663424d90 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424fd0 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424d90 2016-08-11 12:17:34.368+0000: 43669: debug : virEventPollInterruptLocked:727 : Interrupting 2016-08-11 12:17:34.368+0000: 43669: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=7 events=1 cb=0x7f9661afbfb0 opaque=0x7f9663424d90 ff=0x7f9661afbf60 2016-08-11 12:17:34.368+0000: 43669: debug : virKeepAliveNew:199 : client=0x7f9663424fd0, interval=-1, count=0 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663424c10 classname=virKeepAlive 2016-08-11 12:17:34.368+0000: 43669: info : virKeepAliveNew:218 : RPC_KEEPALIVE_NEW: ka=0x7f9663424c10 client=0x7f9663424fd0 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424fd0 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663421f20 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollRunOnce:651 : Poll got 1 event(s) 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchTimeouts:433 : Dispatch 1 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f96634249f0 classname=virNetClientProgram 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchHandles:479 : Dispatch 1 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchHandles:493 : i=0 w=1 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663424ba0 classname=virNetClientProgram 2016-08-11 12:17:34.368+0000: 43669: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f9663424950 classname=virNetClientProgram 2016-08-11 12:17:34.368+0000: 43670: info : virEventPollDispatchHandles:507 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f96634249f0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424ba0 2016-08-11 12:17:34.368+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424950 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 2 2016-08-11 12:17:34.368+0000: 43669: debug : doRemoteOpen:1010 : Trying authentication 2016-08-11 12:17:34.368+0000: 43670: debug : virEventRunDefaultImpl:305 : running default event implementation 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.368+0000: 43669: debug : virNetMessageNew:46 : msg=0x7f96634251e0 tracked=0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 2 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2016-08-11 12:17:34.368+0000: 43669: debug : virNetMessageEncodePayload:376 : Encode length as 28 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers 2016-08-11 12:17:34.368+0000: 43669: info : virNetClientSendInternal:1950 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f9663424fd0 len=28 prog=536903814 vers=1 proc=66 type=0 status=0 serial=0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCalculateTimeout:371 : No timeout is pending 2016-08-11 12:17:34.368+0000: 43669: debug : virNetClientCallNew:1903 : New call 0x7f9663425100: msg=0x7f96634251e0, expectReply=1, nonBlock=0 2016-08-11 12:17:34.368+0000: 43670: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=2 timeout=-1 2016-08-11 12:17:34.368+0000: 43669: debug : virNetClientIO:1712 : Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 dispatch=(nil) 2016-08-11 12:17:34.368+0000: 43669: debug : virNetClientIO:1771 : We have the buck head=0x7f9663425100 call=0x7f9663425100 2016-08-11 12:17:34.368+0000: 43669: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=0 2016-08-11 12:17:34.368+0000: 43669: debug : virEventPollInterruptLocked:727 : Interrupting 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollRunOnce:651 : Poll got 1 event(s) 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchTimeouts:433 : Dispatch 1 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchHandles:479 : Dispatch 2 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollDispatchHandles:493 : i=0 w=1 2016-08-11 12:17:34.368+0000: 43670: info : virEventPollDispatchHandles:507 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 2 2016-08-11 12:17:34.368+0000: 43670: debug : virEventRunDefaultImpl:305 : running default event implementation 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.368+0000: 43671: info : libvirt version: 1.2.17, package: 13.el7_2.5 (CentOS BuildSystem <http://bugs.centos.org>;, 2016-06-23-14:23:27, worker1.bsys.centos.org) 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 2 2016-08-11 12:17:34.368+0000: 43671: debug : virExec:730 : Setting child uid:gid to -1:-1 with caps 0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=0 d=0 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers 2016-08-11 12:17:34.368+0000: 43670: debug : virEventPollCalculateTimeout:371 : No timeout is pending 2016-08-11 12:17:34.368+0000: 43670: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2016-08-11 12:17:34.632+0000: 43669: error : virNetSocketReadWire:1590 : End of file while reading data: 2016-08-11 12:17:34.368+0000: 43671: debug : virFileClose:102 : Closed fd 8 2016-08-11 12:17:34.368+0000: 43671: debug : virFileClose:102 : Closed fd 10 2016-08-11 12:17:34.368+0000: 43671: debug : virLogParseOutputs:1091 : outputs=1:file:/tmp/libvirt_client.log: Input/output error 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientMarkClose:638 : client=0x7f9663424fd0, reason=0 2016-08-11 12:17:34.632+0000: 43669: info : virEventPollRemoveHandle:186 : EVENT_POLL_REMOVE_HANDLE: watch=2 2016-08-11 12:17:34.632+0000: 43669: debug : virEventPollRemoveHandle:199 : mark delete 1 7 2016-08-11 12:17:34.632+0000: 43669: debug : virEventPollInterruptLocked:727 : Interrupting 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientIOEventLoopPassTheBuck:1419 : Giving up the buck 0x7f9663425100 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientIOEventLoopPassTheBuck:1433 : No thread to pass the buck to 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientCloseLocked:654 : client=0x7f9663424fd0, sock=0x7f9663424d90, reason=0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424d90 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollRunOnce:651 : Poll got 1 event(s) 2016-08-11 12:17:34.632+0000: 43669: info : virObjectRef:296 : OBJECT_REF: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchTimeouts:433 : Dispatch 1 2016-08-11 12:17:34.632+0000: 43669: info : virKeepAliveStop:310 : RPC_KEEPALIVE_STOP: ka=0x7f9663424c10 client=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424c10 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchHandles:479 : Dispatch 1 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663424c10 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchHandles:493 : i=0 w=1 2016-08-11 12:17:34.632+0000: 43669: info : virKeepAliveDispose:230 : RPC_KEEPALIVE_DISPOSE: ka=0x7f9663424c10 2016-08-11 12:17:34.632+0000: 43670: info : virEventPollDispatchHandles:507 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 2 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientIO:1801 : All done with our call head=(nil) call=0x7f9663425100 rv=-1 2016-08-11 12:17:34.632+0000: 43670: info : virEventPollCleanupHandles:588 : EVENT_POLL_PURGE_HANDLE: watch=2 2016-08-11 12:17:34.632+0000: 43669: debug : virNetMessageFree:74 : msg=0x7f96634251e0 nfds=0 cb=(nil) 2016-08-11 12:17:34.632+0000: 43670: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f96634249f0 2016-08-11 12:17:34.632+0000: 43670: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424d90 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424ba0 2016-08-11 12:17:34.632+0000: 43670: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663424d90 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424950 2016-08-11 12:17:34.632+0000: 43670: info : virNetSocketDispose:1155 : RPC_SOCKET_DISPOSE: sock=0x7f9663424d90 2016-08-11 12:17:34.632+0000: 43669: debug : virNetClientCloseInternal:695 : client=0x7f9663424fd0 wantclose=0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43669: info : virNetClientDispose:606 : RPC_CLIENT_DISPOSE: client=0x7f9663424fd0 2016-08-11 12:17:34.632+0000: 43670: debug : virFileClose:102 : Closed fd 7 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663421f20 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f96634249f0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f96634249f0 2016-08-11 12:17:34.632+0000: 43670: debug : virFileClose:102 : Closed fd 9 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424ba0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663424ba0 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663424950 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663424950 2016-08-11 12:17:34.632+0000: 43670: debug : virProcessAbort:167 : aborting child process 43671 2016-08-11 12:17:34.632+0000: 43669: debug : virFileClose:102 : Closed fd 10 2016-08-11 12:17:34.632+0000: 43669: debug : virFileClose:102 : Closed fd 8 2016-08-11 12:17:34.632+0000: 43669: debug : virNetMessageClear:57 : msg=0x7f9663425038 nfds=0 2016-08-11 12:17:34.632+0000: 43669: debug : do_open:1194 : driver 2 remote returned ERROR 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663423ec0 2016-08-11 12:17:34.632+0000: 43670: debug : virProcessAbort:172 : process has ended: exit status 1 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663423ec0 2016-08-11 12:17:34.632+0000: 43670: debug : virEventRunDefaultImpl:305 : running default event implementation 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f9663421f20 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 1 2016-08-11 12:17:34.632+0000: 43669: info : virObjectUnref:261 : OBJECT_DISPOSE: obj=0x7f9663421f20 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 1 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCalculateTimeout:371 : No timeout is pending 2016-08-11 12:17:34.632+0000: 43670: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=1 timeout=-1 2016-08-11 12:17:34.632+0000: 43669: debug : virEventPollInterruptLocked:727 : Interrupting 2016-08-11 12:17:34.632+0000: 43669: info : virEventPollAddTimeout:253 : EVENT_POLL_ADD_TIMEOUT: timer=2 frequency=0 cb=0x7f96620b7ae0 opaque=(nil) ff=(nil) 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollRunOnce:651 : Poll got 1 event(s) 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchTimeouts:433 : Dispatch 2 2016-08-11 12:17:34.632+0000: 43670: info : virEventPollDispatchTimeouts:456 : EVENT_POLL_DISPATCH_TIMEOUT: timer=2 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchHandles:479 : Dispatch 1 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollDispatchHandles:493 : i=0 w=1 2016-08-11 12:17:34.632+0000: 43670: info : virEventPollDispatchHandles:507 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupTimeouts:526 : Cleanup 2 2016-08-11 12:17:34.632+0000: 43670: debug : virEventPollCleanupHandles:575 : Cleanup 1 2016-08-11 12:17:34.632+0000: 43670: debug : virThreadJobClear:124 : Thread 43670 finished job vshEventLoop with ret=0 2016-08-11 12:17:34.632+0000: 43669: info : virEventPollRemoveTimeout:305 : EVENT_POLL_REMOVE_TIMEOUT: timer=2 2016-08-11 12:17:34.632+0000: 43669: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 140283594831616 2016-08-11 12:17:34.632+0000: 43669: info : virEventPollRemoveTimeout:305 : EVENT_POLL_REMOVE_TIMEOUT: timer=1 2016-08-11 12:17:34.632+0000: 43669: debug : virEventPollInterruptLocked:723 : Skip interrupt, 0 140283594831616