At this stage you are trying to add a host to not compatible cluster: 2015-10-26 15:17:25,568 INFO [org.ovirt.engine.core.vdsbroker.HostMonitoring] (DefaultQuartzScheduler_Worker-81) [33e54172] Host 'infraesx2'(da97f61d-bc4c-46c5-b924-69553b1f85c2) is already in NonOperational status for reason 'EMULATED_MACHINES_INCOMPATIBLE_WITH_CLUSTER_LEVEL'. SetNonOperationalVds command is skipped. Please make sure that you host and cluster version match. I can see that when you resolved naming issue you can talk to your host now. On Mon, Oct 26, 2015 at 10:59 AM, Budur Nagaraju <nbudoor@gmail.com> wrote:
Host name resolved but now am getting below log,
[root@cstlb1 ~]# tail -f /var/log/ovirt-engine/engine.log 2015-10-26 15:17:25,420 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzScheduler_Worker-81) [1b37c8d6] FINISH, SetVdsStatusVDSCommand, log id: 1c9035d1 2015-10-26 15:17:25,464 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-81) [1b37c8d6] Correlation ID: 1b37c8d6, Job ID: 364e1eff-2dc7-40ba-801c-4e0c38f5f833, Call Stack: null, Custom Event ID: -1, Message: Host infraesx2 does not comply with the cluster Default emulated machines. The current cluster compatibility level supports [pc-i440fx-rhel7.2.0, pc-i440fx-2.1, pseries-rhel7.2.0] and the host emulated machines are pc-i440fx-rhel7.1.0,rhel6.3.0,pc-q35-rhel7.0.0,rhel6.1.0,rhel6.6.0,rhel6.2.0,pc,pc-q35-rhel7.1.0,q35,rhel6.4.0,rhel6.0.0,rhel6.5.0,pc-i440fx-rhel7.0.0. 2015-10-26 15:17:25,525 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (DefaultQuartzScheduler_Worker-81) [1b37c8d6] START, GetHardwareInfoVDSCommand(HostName = infraesx2, VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', hostId='da97f61d-bc4c-46c5-b924-69553b1f85c2', vds='Host[infraesx2,da97f61d-bc4c-46c5-b924-69553b1f85c2]'}), log id: 28e652ce 2015-10-26 15:17:25,529 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (DefaultQuartzScheduler_Worker-81) [1b37c8d6] FINISH, GetHardwareInfoVDSCommand, log id: 28e652ce 2015-10-26 15:17:25,544 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (DefaultQuartzScheduler_Worker-81) [7f2d661e] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:17:25,551 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-81) [7f2d661e] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Status of host infraesx2 was set to NonOperational. 2015-10-26 15:17:25,563 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (DefaultQuartzScheduler_Worker-81) [56c866db] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:17:25,566 INFO [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (DefaultQuartzScheduler_Worker-81) [33e54172] Running command: HandleVdsVersionCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:17:25,568 INFO [org.ovirt.engine.core.vdsbroker.HostMonitoring] (DefaultQuartzScheduler_Worker-81) [33e54172] Host 'infraesx2'(da97f61d-bc4c-46c5-b924-69553b1f85c2) is already in NonOperational status for reason 'EMULATED_MACHINES_INCOMPATIBLE_WITH_CLUSTER_LEVEL'. SetNonOperationalVds command is skipped. 2015-10-26 15:18:20,097 ERROR [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder] (default task-7) [] Failed to find host on any provider by host name 'cstlb1' 2015-10-26 15:27:34,926 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (default task-3) [3dcf3370] Lock Acquired to object 'EngineLock:{exclusiveLocks='[da97f61d-bc4c-46c5-b924-69553b1f85c2=<VDS, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}' 2015-10-26 15:27:34,936 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Running command: ActivateVdsCommand internal: false. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDSAction group MANIPULATE_HOST with role type ADMIN 2015-10-26 15:27:34,937 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Before acquiring lock in order to prevent monitoring for host 'infraesx2' from data-center 'Default' 2015-10-26 15:27:34,938 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Lock acquired, from now a monitoring of host will be skipped for host 'infraesx2' from data-center 'Default' 2015-10-26 15:27:34,941 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] START, SetVdsStatusVDSCommand(HostName = infraesx2, SetVdsStatusVDSCommandParameters:{runAsync='true', hostId='da97f61d-bc4c-46c5-b924-69553b1f85c2', status='Unassigned', nonOperationalReason='NONE', stopSpmFailureLogged='false', maintenanceReason='null'}), log id: 3b297b7c 2015-10-26 15:27:34,942 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] FINISH, SetVdsStatusVDSCommand, log id: 3b297b7c 2015-10-26 15:27:34,946 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Activate finished. Lock released. Monitoring can run now for host 'infraesx2' from data-center 'Default' 2015-10-26 15:27:34,948 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Correlation ID: 3dcf3370, Job ID: b0c5598f-c5a8-4850-a5d1-207f3fc68ac2, Call Stack: null, Custom Event ID: -1, Message: Activation of host infraesx2 initiated by admin@internal. 2015-10-26 15:27:34,951 INFO [org.ovirt.engine.core.bll.ActivateVdsCommand] (org.ovirt.thread.pool-8-thread-36) [3dcf3370] Lock freed to object 'EngineLock:{exclusiveLocks='[da97f61d-bc4c-46c5-b924-69553b1f85c2=<VDS, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}' 2015-10-26 15:27:35,027 ERROR [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder] (default task-16) [] Failed to find host on any provider by host name 'cstlb1' 2015-10-26 15:27:35,038 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (DefaultQuartzScheduler_Worker-68) [] START, GetHardwareInfoVDSCommand(HostName = infraesx2, VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', hostId='da97f61d-bc4c-46c5-b924-69553b1f85c2', vds='Host[infraesx2,da97f61d-bc4c-46c5-b924-69553b1f85c2]'}), log id: 7f0adc20 2015-10-26 15:27:35,046 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (DefaultQuartzScheduler_Worker-68) [] FINISH, GetHardwareInfoVDSCommand, log id: 7f0adc20 2015-10-26 15:27:35,059 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (DefaultQuartzScheduler_Worker-68) [7a980412] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:27:35,069 INFO [org.ovirt.engine.core.bll.SetNonOperationalVdsCommand] (DefaultQuartzScheduler_Worker-68) [736dbf8b] Running command: SetNonOperationalVdsCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:27:35,071 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzScheduler_Worker-68) [736dbf8b] START, SetVdsStatusVDSCommand(HostName = infraesx2, SetVdsStatusVDSCommandParameters:{runAsync='true', hostId='da97f61d-bc4c-46c5-b924-69553b1f85c2', status='NonOperational', nonOperationalReason='EMULATED_MACHINES_INCOMPATIBLE_WITH_CLUSTER_LEVEL', stopSpmFailureLogged='false', maintenanceReason='null'}), log id: 2f9d5205 2015-10-26 15:27:35,073 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzScheduler_Worker-68) [736dbf8b] FINISH, SetVdsStatusVDSCommand, log id: 2f9d5205 2015-10-26 15:27:35,079 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-68) [736dbf8b] Correlation ID: 736dbf8b, Job ID: fb8ca820-87be-4910-ae96-0f91397dd42b, Call Stack: null, Custom Event ID: -1, Message: Host infraesx2 does not comply with the cluster Default emulated machines. The current cluster compatibility level supports [pc-i440fx-rhel7.2.0, pc-i440fx-2.1, pseries-rhel7.2.0] and the host emulated machines are pc-i440fx-rhel7.1.0,rhel6.3.0,pc-q35-rhel7.0.0,rhel6.1.0,rhel6.6.0,rhel6.2.0,pc,pc-q35-rhel7.1.0,q35,rhel6.4.0,rhel6.0.0,rhel6.5.0,pc-i440fx-rhel7.0.0. 2015-10-26 15:27:35,083 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-68) [736dbf8b] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Status of host infraesx2 was set to NonOperational. 2015-10-26 15:27:35,091 INFO [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (DefaultQuartzScheduler_Worker-68) [5a847352] Running command: HandleVdsVersionCommand internal: true. Entities affected : ID: da97f61d-bc4c-46c5-b924-69553b1f85c2 Type: VDS 2015-10-26 15:27:35,092 INFO [org.ovirt.engine.core.vdsbroker.HostMonitoring] (DefaultQuartzScheduler_Worker-68) [5a847352] Host 'infraesx2'(da97f61d-bc4c-46c5-b924-69553b1f85c2) is already in NonOperational status for reason 'EMULATED_MACHINES_INCOMPATIBLE_WITH_CLUSTER_LEVEL'. SetNonOperationalVds command is skipped. 2015-10-26 15:27:35,550 ERROR [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder] (default task-9) [] Failed to find host on any provider by host name 'cstlb1' 2015-10-26 15:27:35,932 ERROR [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder] (default task-1) [] Failed to find host on any provider by host name 'cstlb1'
On Mon, Oct 26, 2015 at 3:19 PM, Piotr Kliczewski <piotr.kliczewski@gmail.com> wrote:
In the engine log this time I can see:
java.net.UnknownHostException: cstlb1: cstlb1: unknown error
which means that the name of the host is not known and this is the issue why the engine is not able to connect.
On Mon, Oct 26, 2015 at 10:37 AM, Budur Nagaraju <nbudoor@gmail.com> wrote:
Attached is the log details.
On Mon, Oct 26, 2015 at 1:35 PM, Piotr Kliczewski <piotr.kliczewski@gmail.com> wrote:
I can see that the dates do not match with engine log that you provided earlier. Please provided vdsm log from the same time frame so we could see why the connection failed. I only found this issue in vdsm logs that you provided:
Thread-493088::ERROR::2015-10-19 07:24:26,102::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/hosted-engine.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'] Thread-493088::ERROR::2015-10-19 07:24:26,102::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/vm.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/vm.conf'] Thread-493088::ERROR::2015-10-19 07:24:26,103::API::1723::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info Traceback (most recent call last): File "/usr/share/vdsm/API.py", line 1703, in _getHaInfo File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 100, in get_all_stats File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID
On Mon, Oct 26, 2015 at 9:00 AM, Budur Nagaraju <nbudoor@gmail.com> wrote:
Below are the logs,
BVEFbYm5nbGFiLnBzZWN1cmUubmV0XV0+PC9Pcmdhbml6YXRpb24+DQogICAgICAgICAgICA8L1VzZXJEYXRhPg0KICAgICAgICAgICAgPEltYWdlSW5zdGFsbD4NCiAgICAgICAgICAgICAgICA8T1NJbWFnZT4NCiAgICAgICAgICAgICAgICAgICAgPEluc3RhbGxUb0F2YWlsYWJsZVBhcnRpdGlvbj50cnVlPC9JbnN0YWxsVG9BdmFpbGFibGVQYXJ0aXRpb24+DQogICAgICAgICAgICAgICAgPC9PU0ltYWdlPg0KICAgICAgICAgICAgPC9JbWFnZUluc3RhbGw+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLUludGVybmF0aW9uYWwtQ29yZS1XaW5QRSIgcHJvY2Vzc29yQXJjaGl0ZWN0dXJlPSJ4ODYiIHB1YmxpY0tleVRva2VuPSIzMWJmMzg1NmFkMzY0ZTM1IiBsYW5ndWFnZT0ibmV1dHJhbCIgdmVyc2lvblNjb3BlPSJub25TeFMiIHhtbG5zOndjbT0iaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS9XTUlDb25maWcvMjAwMi9TdGF0ZSIgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYS1pbnN0YW5jZSI+DQogICAgICAgICAgICA8U2V0dXBVSUxhbmd1YWdlPg0KICAgICAgICAgICAgICAgIDxVSUxhbmd1YWdlPjwhW0NEQVRBW2VuX1VTXV0+PC9VSUxhbmd1YWdlPg0KICAgICAgICAgICAgPC9TZXR1cFVJTGFuZ3VhZ2U+DQogICAgICAgICAgICA8SW5wdXRMb2NhbGU+PCFbQ0RBVEFbZW5fVVNdXT48L0lucHV0TG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgICAgICA8U3lzdGVtTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9TeXN0ZW1Mb2NhbGU+DQogICAgICAgICAgICA8VXNlckxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvVXNlckxvY2FsZT4NCiAgICAgICAgPC9jb21wb25lbnQ+DQogICAgPC9zZXR0aW5ncz4NCiAgICA8c2V0dGluZ3MgcGFzcz0ic3BlY2lhbGl6ZSI+DQogICAgICAgIDxjb21wb25lbnQgbmFtZT0iTWljcm9zb2Z0LVdpbmRvd3MtU2hlbGwtU2V0dXAiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPERpc3BsYXk+DQogICAgICAgICAgICAgICAgPENvbG9yRGVwdGg+MzI8L0NvbG9yRGVwdGg+DQogICAgICAgICAgICAgICAgPERQST45NjwvRFBJPg0KICAgICAgICAgICAgICAgIDxIb3Jpem9udGFsUmVzb2x1dGlvbj4xMDI0PC9Ib3Jpem9udGFsUmVzb2x1dGlvbj4NCiAgICAgICAgICAgICAgICA8UmVmcmVzaFJhdGU+NzU8L1JlZnJlc2hSYXRlPg0KICAgICAgICAgICAgICAgIDxWZXJ0aWNhbFJlc29sdXRpb24+NzY4PC9WZXJ0aWNhbFJlc29sdXRpb24+DQogICAgICAgICAgICA8L0Rpc3BsYXk+DQogICAgICAgICAgICA8Q29tcHV0ZXJOYW1lPjwhW0NEQVRBW1Rlc3Qtd2luOC0xXV0+PC9Db21wdXRlck5hbWU+DQogICAgICAgICAgICA8VGltZVpvbmU+PCFbQ0RBVEFbR01UIFN0YW5kYXJkIFRpbWVdXT48L1RpbWVab25lPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICAgICAgPGNvbXBvbmVudCBuYW1lPSJNaWNyb3NvZnQtV2luZG93cy1JbnRlcm5hdGlvbmFsLUNvcmUiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElucHV0TG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9JbnB1dExvY2FsZT4NCiAgICAgICAgICAgIDxVc2VyTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9Vc2VyTG9jYWxlPg0KICAgICAgICAgICAgPFN5c3RlbUxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvU3lzdGVtTG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLVVuYXR0ZW5kZWRKb2luIiBwcm9jZXNzb3JBcmNoaXRlY3R1cmU9ImFtZDY0IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElkZW50aWZpY2F0aW9uPg0KICAgICAgICAgICAgICAgIDxDcmVkZW50aWFscz4NCiAgICAgICAgICAgICAgICAgICAgPERvbWFpbj48IVtDREFUQVtdXT48L0RvbWFpbj4NCiAgICAgICAgICAgICAgICAgICAgPFBhc3N3b3JkPjwhW0NEQVRBW11dPjwvUGFzc3dvcmQ+DQogICAgICAgICAgICAgICAgICAgIDxVc2VybmFtZT48IVtDREFUQVtdXT48L1VzZXJuYW1lPg0KICAgICAgICAgICAgICAgIDwvQ3JlZGVudGlhbHM+DQogICAgICAgICAgICAgICAgPEpvaW5Eb21haW4+PCFbQ0RBVEFbXV0+PC9Kb2luRG9tYWluPg0KICAgICAgICAgICAgICAgIDxNYWNoaW5lT2JqZWN0T1U+PCFbQ0RBVEFbXV0+PC9NYWNoaW5lT2JqZWN0T1U+DQogICAgICAgICAgICA8L0lkZW50aWZpY2F0aW9uPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICA8L3NldHRpbmdzPg0KICAgIDxzZXR0aW5ncyBwYXNzPSJvb2JlU3lzdGVtIj4NCiAgICAgICAgPGNvbXBvbmVudCBuYW1lPSJNaWNyb3NvZnQtV2luZG93cy1JbnRlcm5hdGlvbmFsLUNvcmUiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElucHV0TG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9JbnB1dExvY2FsZT4NCiAgICAgICAgICAgIDxVc2VyTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9Vc2VyTG9jYWxlPg0KICAgICAgICAgICAgPFN5c3RlbUxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvU3lzdGVtTG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLVNoZWxsLVNldHVwIiBwcm9jZXNzb3JBcmNoaXRlY3R1cmU9ImFtZDY0IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPE9PQkU+DQogICAgICAgICAgICAgICAgPFByb3RlY3RZb3VyUEM+MjwvUHJvdGVjdFlvdXJQQz4NCiAgICAgICAgICAgICAgICA8TmV0d29ya0xvY2F0aW9uPldvcms8L05ldHdvcmtMb2NhdGlvbj4NCiAgICAgICAgICAgICAgICA8SGlkZUVVTEFQYWdlPnRydWU8L0hpZGVFVUxBUGFnZT4NCiAgICAgICAgICAgIDwvT09CRT4NCiAgICAgICAgICAgIDxVc2VyQWNjb3VudHM+DQogICAgICAgICAgICAgICAgPEFkbWluaXN0cmF0b3JQYXNzd29yZD4NCiAgICAgICAgICAgICAgICAgICAgPFZhbHVlPjwhW0NEQVRBW0VtYmUxbXBsc11dPjwvVmFsdWU+DQogICAgICAgICAgICAgICAgICAgIDxQbGFpblRleHQ+dHJ1ZTwvUGxhaW5UZXh0Pg0KICAgICAgICAgICAgICAgIDwvQWRtaW5pc3RyYXRvclBhc3N3b3JkPg0KICAgICAgICAgICAgICAgIDxMb2NhbEFjY291bnRzPg0KICAgICAgICAgICAgICAgICAgICA8TG9jYWxBY2NvdW50IHdjbTphY3Rpb249ImFkZCI+DQogICAgICAgICAgICAgICAgICAgICAgICA8UGFzc3dvcmQ+DQogICAgICAgICAgICAgICAgICAgICAgICAgICAgPFZhbHVlPjwhW0NEQVRBW0VtYmUxbXBsc11dPjwvVmFsdWU+DQogICAgICAgICAgICAgICAgICAgICAgICAgICAgPFBsYWluVGV4dD50cnVlPC9QbGFpblRleHQ+DQogICAgICAgICAgICAgICAgICAgICAgICA8L1Bhc3N3b3JkPg0KICAgICAgICAgICAgICAgICAgICAgICAgPEdyb3VwPmFkbWluaXN0cmF0b3JzPC9Hcm91cD4NCiAgICAgICAgICAgICAgICAgICAgICAgIDxOYW1lPnVzZXI8L05hbWU+DQogICAgICAgICAgICAgICAgICAgICAgICA8RGlzcGxheU5hbWU+dXNlcjwvRGlzcGxheU5hbWU+DQogICAgICAgICAgICAgICAgICAgIDwvTG9jYWxBY2NvdW50Pg0KICAgICAgICAgICAgICAgIDwvTG9jYWxBY2NvdW50cz4NCiAgICAgICAgICAgIDwvVXNlckFjY291bnRzPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICA8L3NldHRpbmdzPg0KICAgIDxjcGk6b2ZmbGluZUltYWdlIGNwaTpzb3VyY2U9IndpbTpkOi9zb3VyY2VzL2luc3RhbGwud2ltI1dpbmRvd3MgOCBFTlRFUlBSSVNFIiB4bWxuczpjcGk9InVybjpzY2hlbWFzLW1pY3Jvc29mdC1jb206Y3BpIi8+DQo8L3VuYXR0ZW5kPg0K'}}}, u'readonly': u'true', 'deviceType': u'disk', u'deviceId': u'c86868ec-4eae-4fb4-b395-165fd3d31ac2', u'shared': u'false', u'device': u'floppy', u'path': u'', u'type': u'disk'}, {u'device': u'qxl', u'specParams': {u'vram': u'32768', u'heads': u'1'}, 'deviceType': u'video', u'type': u'video', u'deviceId': u'a62472d7-007a-403a-9880-d7e62d9e9a02'}, {u'index': u'2', u'iface': u'ide', u'specParams': {u'path': u''}, u'readonly': u'true', 'deviceType': u'disk', u'deviceId': u'fc33f0e3-3a7c-4dc2-a4c5-0d8134766c4d', u'shared': u'false', u'device': u'cdrom', u'path':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso', u'type': u'disk'}, {u'index': 0, u'iface': u'ide', u'type': u'disk', u'format': u'cow', u'bootOrder': u'1', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', u'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224', u'specParams': {}, u'readonly': u'false', u'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'deviceType': u'disk', u'deviceId': u'91dce925-129e-4de5-a5af-bbdbe9d80224', u'poolID': u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', u'device': u'disk', u'shared': u'false', u'propagateErrors': u'off', u'optional': u'false'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:79:9e:06', u'linkActive': u'true', u'network': u'ovirtmgmt', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, 'deviceType': u'interface', u'deviceId': u'4c57d9ac-b4cf-4602-9c0f-fd034cb91aba', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface'}, {u'specParams': {}, 'deviceType': u'sound', u'deviceId': u'14cc528b-dd7c-4047-8f7c-224c67100163', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'ich6', u'type': u'sound'}, {u'index': u'0', u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'5151af56-76f6-43c9-9ac5-7df7525ea04b', u'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'0b738f8b-7f8d-4740-ad24-2458387e330b', u'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}], u'timeOffset': u'19800', u'maxVCpus': u'16', u'spiceSecureChannels':
u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'} Thread-493084::DEBUG::2015-10-19 07:24:22,481::task::595::Storage.TaskManager.Task::(_updateState) Task=`8b23488e-3ef1-45b0-b86b-819ef8bed42c`::moving from state init -> state preparing Thread-493083::DEBUG::2015-10-19 07:24:22,481::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-493084::INFO::2015-10-19 07:24:22,483::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'91dce925-129e-4de5-a5af-bbdbe9d80224', volUUID=u'27589b5c-0c6f-4551-8199-e80c870c9d2a', options=None) Thread-493084::INFO::2015-10-19 07:24:22,487::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '200704', 'apparentsize': '197120'} Thread-493084::DEBUG::2015-10-19 07:24:22,487::task::1191::Storage.TaskManager.Task::(prepare) Task=`8b23488e-3ef1-45b0-b86b-819ef8bed42c`::finished: {'truesize': '200704', 'apparentsize': '197120'} Thread-493084::DEBUG::2015-10-19 07:24:22,487::task::595::Storage.TaskManager.Task::(_updateState) Task=`8b23488e-3ef1-45b0-b86b-819ef8bed42c`::moving from state preparing -> state finished Thread-493084::DEBUG::2015-10-19
07:24:22,487::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-493084::DEBUG::2015-10-19
07:24:22,487::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493084::DEBUG::2015-10-19 07:24:22,488::task::993::Storage.TaskManager.Task::(_decref) Task=`8b23488e-3ef1-45b0-b86b-819ef8bed42c`::ref 0 aborting False Thread-493084::INFO::2015-10-19 07:24:22,522::clientIF::337::vds::(prepareVolumePath) prepared volume path:
/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img Thread-493084::INFO::2015-10-19 07:24:22,522::clientIF::337::vds::(prepareVolumePath) prepared volume path:
/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso Thread-493084::DEBUG::2015-10-19 07:24:22,523::task::595::Storage.TaskManager.Task::(_updateState) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::moving from state init -> state preparing Thread-493084::INFO::2015-10-19 07:24:22,523::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'91dce925-129e-4de5-a5af-bbdbe9d80224', leafUUID=u'27589b5c-0c6f-4551-8199-e80c870c9d2a') Thread-493084::DEBUG::2015-10-19
07:24:22,524::resourceManager::198::Storage.ResourceManager.Request::(__init__)
ResName=`Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302`ReqID=`c7667eb5-ac03-4f00-bfe2-65ea9d34faca`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3226' at 'prepareImage' Thread-493084::DEBUG::2015-10-19
07:24:22,524::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302' for lock type 'shared' Thread-493084::DEBUG::2015-10-19
07:24:22,525::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302' is free. Now locking as 'shared' (1 active user) Thread-493084::DEBUG::2015-10-19
07:24:22,525::resourceManager::238::Storage.ResourceManager.Request::(grant)
ResName=`Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302`ReqID=`c7667eb5-ac03-4f00-bfe2-65ea9d34faca`::Granted request Thread-493084::DEBUG::2015-10-19 07:24:22,526::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::_resourcesAcquired: Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302 (shared) Thread-493084::DEBUG::2015-10-19 07:24:22,527::task::993::Storage.TaskManager.Task::(_decref) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::ref 1 aborting False Thread-493084::DEBUG::2015-10-19 07:24:22,545::fileSD::521::Storage.StorageDomain::(activateVolumes) Fixing permissions on
/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a Thread-493084::DEBUG::2015-10-19 07:24:22,546::fileSD::521::Storage.StorageDomain::(activateVolumes) Fixing permissions on
/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403 Thread-493084::DEBUG::2015-10-19 07:24:22,547::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/49d4a9cd-946d-41e0-a7ae-f2620f010302 Thread-493084::WARNING::2015-10-19 07:24:22,547::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/49d4a9cd-946d-41e0-a7ae-f2620f010302 already exists Thread-493084::DEBUG::2015-10-19 07:24:22,547::fileSD::496::Storage.StorageDomain::(createImageLinks) Creating symlink from
/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224 to
/var/run/vdsm/storage/49d4a9cd-946d-41e0-a7ae-f2620f010302/91dce925-129e-4de5-a5af-bbdbe9d80224 Thread-493084::DEBUG::2015-10-19 07:24:22,550::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 27589b5c-0c6f-4551-8199-e80c870c9d2a Thread-493084::DEBUG::2015-10-19 07:24:22,553::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 60d7aa2a-9850-43f2-a523-64c9dda8e403 Thread-493084::INFO::2015-10-19 07:24:22,555::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}, 'path':
u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'imgVolumesInfo': [{'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}, {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403', 'volumeID': u'60d7aa2a-9850-43f2-a523-64c9dda8e403', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}]} Thread-493084::DEBUG::2015-10-19 07:24:22,555::task::1191::Storage.TaskManager.Task::(prepare) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::finished: {'info': {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}, 'path':
u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'imgVolumesInfo': [{'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}, {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403', 'volumeID': u'60d7aa2a-9850-43f2-a523-64c9dda8e403', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224'}]} Thread-493084::DEBUG::2015-10-19 07:24:22,556::task::595::Storage.TaskManager.Task::(_updateState) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::moving from state preparing -> state finished Thread-493084::DEBUG::2015-10-19
07:24:22,556::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302': < ResourceRef 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302', isValid: 'True' obj: 'None'>} Thread-493084::DEBUG::2015-10-19
07:24:22,556::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493084::DEBUG::2015-10-19
07:24:22,556::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302' Thread-493084::DEBUG::2015-10-19
07:24:22,556::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302' (0 active users) Thread-493084::DEBUG::2015-10-19
07:24:22,556::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302' is free, finding out if anyone is waiting for it. Thread-493084::DEBUG::2015-10-19
07:24:22,557::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.49d4a9cd-946d-41e0-a7ae-f2620f010302', Clearing records. Thread-493084::DEBUG::2015-10-19 07:24:22,557::task::993::Storage.TaskManager.Task::(_decref) Task=`202bd711-ec83-485f-82fb-ddcbef85d00c`::ref 0 aborting False Thread-493084::INFO::2015-10-19 07:24:22,557::clientIF::337::vds::(prepareVolumePath) prepared volume path:
/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a Thread-493084::DEBUG::2015-10-19 07:24:22,581::utils::739::root::(execCmd) /usr/libexec/vdsm/hooks/before_vm_start/50_hostedengine (cwd None) Thread-493084::DEBUG::2015-10-19 07:24:22,747::utils::759::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0 Thread-493084::INFO::2015-10-19 07:24:22,748::hooks::100::root::(_runHooksDir) Thread-493084::DEBUG::2015-10-19 07:24:22,748::vm::3313::vm.Vm::(_run) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::<?xml version="1.0" encoding="utf-8"?> <domain type="kvm"> <name>Test-win8-1</name> <uuid>523a9aa2-f60c-4cd7-963a-da678e692218</uuid> <memory>2097152</memory> <currentMemory>2097152</currentMemory> <vcpu current="1">16</vcpu> <devices> <channel type="unix"> <target name="com.redhat.rhevm.vdsm" type="virtio"/> <source mode="bind"
path="/var/lib/libvirt/qemu/channels/523a9aa2-f60c-4cd7-963a-da678e692218.com.redhat.rhevm.vdsm"/> </channel> <channel type="unix"> <target name="org.qemu.guest_agent.0" type="virtio"/> <source mode="bind"
path="/var/lib/libvirt/qemu/channels/523a9aa2-f60c-4cd7-963a-da678e692218.org.qemu.guest_agent.0"/> </channel> <input bus="ps2" type="mouse"/> <sound model="ich6"> <address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/> </sound> <memballoon model="none"/> <controller index="0" model="virtio-scsi" type="scsi"> <address bus="0x00" domain="0x0000" function="0x0" slot="0x05" type="pci"/> </controller> <controller index="0" ports="16" type="virtio-serial"> <address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/> </controller> <video> <model heads="1" type="qxl" vram="32768"/> </video> <graphics autoport="yes" keymap="en-us" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice"> <channel mode="secure" name="main"/> <channel mode="secure" name="inputs"/> <channel mode="secure" name="cursor"/> <channel mode="secure" name="playback"/> <channel mode="secure" name="record"/> <channel mode="secure" name="display"/> <channel mode="secure" name="usbredir"/> <channel mode="secure" name="smartcard"/> <listen network="vdsm-ovirtmgmt" type="network"/> </graphics> <interface type="bridge"> <address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/> <mac address="00:1a:4a:79:9e:06"/> <model type="virtio"/> <source bridge="ovirtmgmt"/> <filterref filter="vdsm-no-mac-spoofing"/> <link state="up"/> <bandwidth/> </interface> <disk device="floppy" snapshot="no" type="file"> <source
file="/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img" startupPolicy="optional"/> <target bus="fdc" dev="fda"/> <readonly/> <serial/> </disk> <disk device="cdrom" snapshot="no" type="file"> <source
file="/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso" startupPolicy="optional"/> <target bus="ide" dev="hdc"/> <readonly/> <serial/> </disk> <disk device="disk" snapshot="no" type="file"> <address bus="0" controller="0" target="0" type="drive" unit="0"/> <source
file="/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a"/> <target bus="ide" dev="hda"/>
<serial>91dce925-129e-4de5-a5af-bbdbe9d80224</serial> <boot order="1"/> <driver cache="none" error_policy="stop" io="threads" name="qemu" type="qcow2"/> </disk> <channel type="spicevmc"> <target name="com.redhat.spice.0" type="virtio"/> </channel> </devices> <os> <type arch="x86_64" machine="rhel6.5.0">hvm</type> <smbios mode="sysinfo"/> </os> <sysinfo type="smbios"> <system> <entry name="manufacturer">oVirt</entry> <entry name="product">oVirt Node</entry> <entry name="version">3.5-0.999.201509102313.el7.centos</entry> <entry name="serial">39333835-3431-4753-4832-323136465732</entry> <entry name="uuid">523a9aa2-f60c-4cd7-963a-da678e692218</entry> </system> </sysinfo> <clock adjustment="19800" offset="variable"> <timer name="rtc" tickpolicy="catchup"/> <timer name="pit" tickpolicy="delay"/> <timer name="hpet" present="no"/> </clock> <features> <acpi/> </features> <cpu match="exact"> <model>Penryn</model> <topology cores="1" sockets="16" threads="1"/> </cpu> </domain>
Thread-493086::DEBUG::2015-10-19 07:24:23,091::stompReactor::162::yajsonrpc.StompServer::(send) Sending response libvirtEventLoop::DEBUG::2015-10-19 07:24:23,400::vm::5590::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::event Started detail 0 opaque None Thread-493084::DEBUG::2015-10-19 07:24:23,430::vm::5430::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Looking for drive with attributes {'name': u'fda', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path':
u'/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img', 'type': u'floppy'} Thread-493084::DEBUG::2015-10-19 07:24:23,430::vm::5451::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'fda', u'fda'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path':
(u'/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img',
u'/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img'), 'type': (u'floppy', u'floppy')} Thread-493084::DEBUG::2015-10-19 07:24:23,430::vm::5470::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'fda', None), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path':
(u'/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img', None), 'type': (u'floppy', None)} Thread-493084::DEBUG::2015-10-19 07:24:23,431::vm::5430::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Looking for drive with attributes {'name': u'hda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7fd4281ec200>], 'readonly': False, 'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path':
u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', 'type': u'disk'} Thread-493084::DEBUG::2015-10-19 07:24:23,431::vm::5451::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'hda', u'hda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7fd4281ec200>], None), 'readonly': (False, False), 'address': ({u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path':
(u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a',
u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a'), 'type': (u'disk', u'disk')} Thread-493084::DEBUG::2015-10-19 07:24:23,432::vm::5470::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'hda', None), 'bootOrder': (u'1', None), 'boot': ([<DOM Element: boot at 0x7fd4281ec200>], None), 'readonly': (False, None), 'address': ({u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path':
(u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', None), 'type': (u'disk', None)} Thread-493084::DEBUG::2015-10-19 07:24:23,432::vm::5430::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso', 'type': u'cdrom'} Thread-493084::DEBUG::2015-10-19 07:24:23,433::vm::5451::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path':
(u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso',
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso'), 'type': (u'cdrom', u'cdrom')} Thread-493084::DEBUG::2015-10-19 07:24:23,433::vm::5470::vm.Vm::(_getUnderlyingDriveInfo) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Matched {'name': (u'hdc', None), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path':
(u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso', None), 'type': (u'cdrom', None)} Thread-493084::DEBUG::2015-10-19 07:24:23,507::sampling::418::vm.Vm::(start) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Start statistics collection Thread-493087::DEBUG::2015-10-19 07:24:23,507::sampling::447::vm.Vm::(run) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Stats thread started Thread-493084::DEBUG::2015-10-19 07:24:23,509::vmchannels::199::vds::(register) Add fileno 46 to listener's channels. Thread-493087::DEBUG::2015-10-19 07:24:23,509::task::595::Storage.TaskManager.Task::(_updateState) Task=`ba7564fc-f062-42fd-86b4-341f821c55f0`::moving from state init -> state preparing Thread-493087::INFO::2015-10-19 07:24:23,510::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=u'49d4a9cd-946d-41e0-a7ae-f2620f010302', spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', imgUUID=u'91dce925-129e-4de5-a5af-bbdbe9d80224', volUUID=u'27589b5c-0c6f-4551-8199-e80c870c9d2a', options=None) Thread-493084::WARNING::2015-10-19 07:24:23,511::vm::4091::vm.Vm::(_readPauseCode) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::_readPauseCode unsupported by libvirt vm Thread-493087::INFO::2015-10-19 07:24:23,514::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '200704', 'apparentsize': '197120'} Thread-493087::DEBUG::2015-10-19 07:24:23,514::task::1191::Storage.TaskManager.Task::(prepare) Task=`ba7564fc-f062-42fd-86b4-341f821c55f0`::finished: {'truesize': '200704', 'apparentsize': '197120'} Thread-493087::DEBUG::2015-10-19 07:24:23,515::task::595::Storage.TaskManager.Task::(_updateState) Task=`ba7564fc-f062-42fd-86b4-341f821c55f0`::moving from state preparing -> state finished Thread-493087::DEBUG::2015-10-19
07:24:23,515::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-493087::DEBUG::2015-10-19
07:24:23,515::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493084::DEBUG::2015-10-19 07:24:23,515::vm::2307::vm.Vm::(_startUnderlyingVm) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::_ongoingCreations released Thread-493087::DEBUG::2015-10-19 07:24:23,517::task::993::Storage.TaskManager.Task::(_decref) Task=`ba7564fc-f062-42fd-86b4-341f821c55f0`::ref 0 aborting False Thread-493087::DEBUG::2015-10-19 07:24:23,540::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present VM Channels Listener::DEBUG::2015-10-19 07:24:23,547::vmchannels::107::vds::(_do_add_channels) fileno 46 was added to unconnected channels. VM Channels Listener::DEBUG::2015-10-19 07:24:23,548::vmchannels::133::vds::(_handle_unconnected) Trying to connect fileno 46. VM Channels Listener::DEBUG::2015-10-19 07:24:23,549::guestagent::201::vm.Vm::(_connect) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Attempting connection to
/var/lib/libvirt/qemu/channels/523a9aa2-f60c-4cd7-963a-da678e692218.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2015-10-19 07:24:23,550::guestagent::204::vm.Vm::(_connect) vmId=`523a9aa2-f60c-4cd7-963a-da678e692218`::Connected to
/var/lib/libvirt/qemu/channels/523a9aa2-f60c-4cd7-963a-da678e692218.com.redhat.rhevm.vdsm VM Channels Listener::DEBUG::2015-10-19 07:24:23,552::vmchannels::149::vds::(_handle_unconnected) Connecting to fileno 46 succeeded. Thread-257233::DEBUG::2015-10-19 07:24:23,854::fileSD::262::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
if=/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None) Thread-257233::DEBUG::2015-10-19 07:24:23,866::fileSD::262::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n329 bytes (329 B) copied, 0.000407316 s, 808 kB/s\n'; <rc> = 0 Dummy-330620::DEBUG::2015-10-19
07:24:24,231::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) dd
if=/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) Dummy-330620::DEBUG::2015-10-19
07:24:24,255::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0133547 s, 76.7 MB/s\n'; <rc> = 0 Thread-493088::DEBUG::2015-10-19 07:24:26,098::task::595::Storage.TaskManager.Task::(_updateState) Task=`a89fc683-1711-4a95-8131-c16af55c0029`::moving from state init -> state preparing Thread-493088::INFO::2015-10-19 07:24:26,099::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-493088::INFO::2015-10-19 07:24:26,099::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00353075', 'lastCheck': '7.1', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00023087', 'lastCheck': '7.1', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000407316', 'lastCheck': '2.2', 'valid': True}} Thread-493088::DEBUG::2015-10-19 07:24:26,099::task::1191::Storage.TaskManager.Task::(prepare) Task=`a89fc683-1711-4a95-8131-c16af55c0029`::finished: {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00353075', 'lastCheck': '7.1', 'valid': True}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00023087', 'lastCheck': '7.1', 'valid': True}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'code': 0, 'actual': True, 'version': 3, 'acquired': True, 'delay': '0.000407316', 'lastCheck': '2.2', 'valid': True}} Thread-493088::DEBUG::2015-10-19 07:24:26,099::task::595::Storage.TaskManager.Task::(_updateState) Task=`a89fc683-1711-4a95-8131-c16af55c0029`::moving from state preparing -> state finished Thread-493088::DEBUG::2015-10-19
07:24:26,099::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-493088::DEBUG::2015-10-19
07:24:26,100::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493088::DEBUG::2015-10-19 07:24:26,100::task::993::Storage.TaskManager.Task::(_decref) Task=`a89fc683-1711-4a95-8131-c16af55c0029`::ref 0 aborting False Thread-493088::ERROR::2015-10-19 07:24:26,102::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/hosted-engine.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'] Thread-493088::ERROR::2015-10-19 07:24:26,102::config::103::ovirt_hosted_engine_ha.env.config::(_load) Configuration file '/etc/ovirt-hosted-engine/vm.conf' not available [[Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/vm.conf'] Thread-493088::ERROR::2015-10-19 07:24:26,103::API::1723::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info Traceback (most recent call last): File "/usr/share/vdsm/API.py", line 1703, in _getHaInfo File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 100, in get_all_stats File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line 173, in _configure_broker_conn File
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/env/config.py", line 129, in get Exception: Configuration value not found: file=/etc/ovirt-hosted-engine/hosted-engine.conf, key=sdUUID Thread-493088::DEBUG::2015-10-19 07:24:26,104::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-493089::DEBUG::2015-10-19 07:24:26,116::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-493090::DEBUG::2015-10-19 07:24:26,124::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getVMFullList' in bridge with {u'vmList': [u'523a9aa2-f60c-4cd7-963a-da678e692218']} Thread-493090::DEBUG::2015-10-19 07:24:26,126::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getVMFullList' in bridge with [{u'acpiEnable': u'true', u'emulatedMachine': u'rhel6.5.0', u'vmId': u'523a9aa2-f60c-4cd7-963a-da678e692218', u'memGuaranteedSize': 1024, u'transparentHugePages': u'true', 'displaySecurePort': u'5902', u'spiceSslCipherSuite': u'DEFAULT', u'cpuType': u'Penryn', u'smp': u'1', 'pauseCode': 'NOERR', u'smartcardEnable': u'false', u'custom':
{u'device_82cf1670-4917-4189-bd96-66141daad620device_fbd208db-983e-4086-bf90-c4d8cd741216': u'VmDevice {vmId=523a9aa2-f60c-4cd7-963a-da678e692218, deviceId=fbd208db-983e-4086-bf90-c4d8cd741216, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=2}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null, logicalName=null}', u'device_82cf1670-4917-4189-bd96-66141daad620': u'VmDevice {vmId=523a9aa2-f60c-4cd7-963a-da678e692218, deviceId=82cf1670-4917-4189-bd96-66141daad620, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null, logicalName=null}',
u'device_82cf1670-4917-4189-bd96-66141daad620device_fbd208db-983e-4086-bf90-c4d8cd741216device_3ac7440a-7f09-468e-bad2-95758e9f5456device_7fecaa8b-ba6b-4690-af3c-ec473c38d1eb': u'VmDevice {vmId=523a9aa2-f60c-4cd7-963a-da678e692218, deviceId=7fecaa8b-ba6b-4690-af3c-ec473c38d1eb, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=1}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null, logicalName=null}',
u'device_82cf1670-4917-4189-bd96-66141daad620device_fbd208db-983e-4086-bf90-c4d8cd741216device_3ac7440a-7f09-468e-bad2-95758e9f5456': u'VmDevice {vmId=523a9aa2-f60c-4cd7-963a-da678e692218, deviceId=3ac7440a-7f09-468e-bad2-95758e9f5456, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=3}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null, logicalName=null}'}, u'vmType': u'kvm', u'memSize': 2048, u'smpCoresPerSocket': u'1', u'vmName': u'Test-win8-1', u'nice': u'0', 'status': 'Up', u'bootMenuEnable': u'false', 'pid': '14998', u'copyPasteEnable': u'true', 'displayIp': '10.206.68.16', 'displayPort': '-1', 'guestDiskMapping': {}, 'clientIp': '', u'fileTransferEnable': u'true', 'nicModel': 'rtl8139,pv', u'keyboardLayout': u'en-us', u'kvmEnable': u'true', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'specParams': {}, 'alias': u'sound0', 'deviceType': u'sound', u'deviceId': u'14cc528b-dd7c-4047-8f7c-224c67100163', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'ich6', u'type': u'sound'}, {'device': 'memballoon', 'specParams': {'model': 'none'}, 'deviceType': 'balloon', 'type': 'balloon', 'alias': u'balloon0'}, {u'index': u'0', 'alias': u'scsi0', u'specParams': {}, 'deviceType': u'controller', u'deviceId': u'5151af56-76f6-43c9-9ac5-7df7525ea04b', u'address': {u'slot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'scsi', u'model': u'virtio-scsi', u'type': u'controller'}, {u'specParams': {}, 'alias': u'virtio-serial0', 'deviceType': u'controller', u'deviceId': u'0b738f8b-7f8d-4740-ad24-2458387e330b', u'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}, {u'specParams': {u'vram': u'32768', u'heads': u'1'}, 'alias': u'video0', 'deviceType': u'video', u'deviceId': u'a62472d7-007a-403a-9880-d7e62d9e9a02', 'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'qxl', u'type': u'video'}, {'device': 'spice', 'specParams': {'displayNetwork': u'ovirtmgmt', 'spiceSecureChannels':
u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'keyMap': u'en-us', 'displayIp': '10.206.68.16', 'copyPasteEnable': u'true'}, 'deviceType': 'graphics', 'type': 'graphics', 'tlsPort': u'5902'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:79:9e:06', u'linkActive': True, u'network': u'ovirtmgmt', u'specParams': {u'inbound': {}, u'outbound': {}}, u'filter': u'vdsm-no-mac-spoofing', 'alias': u'net0', 'deviceType': u'interface', u'deviceId': u'4c57d9ac-b4cf-4602-9c0f-fd034cb91aba', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', 'name': u'vnet2'}, {u'index': u'0', u'iface': u'fdc', 'name': u'fda', 'alias': u'fdc0-0-0', u'specParams': {u'vmPayload': {u'file': {u'Unattend.xml':
u'PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiPz4NCjx1bmF0dGVuZCB4bWxucz0idXJuOnNjaGVtYXMtbWljcm9zb2Z0LWNvbTp1bmF0dGVuZCI+DQogICAgPHNldHRpbmdzIHBhc3M9IndpbmRvd3NQRSI+DQogICAgICAgIDxjb21wb25lbnQgbmFtZT0iTWljcm9zb2Z0LVdpbmRvd3MtU2V0dXAiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPFVzZXJEYXRhPg0KICAgICAgICAgICAgICAgIDxQcm9kdWN0S2V5Pg0KICAgICAgICAgICAgICAgICAgICA8S2V5PjwhW0NEQVRBW11dPjwvS2V5Pg0KICAgICAgICAgICAgICAgIDwvUHJvZHVjdEtleT4NCiAgICAgICAgICAgICAgICA8QWNjZXB0RXVsYT50cnVlPC9BY2NlcHRFdWxhPg0KICAgICAgICAgICAgICAgIDxGdWxsTmFtZT4idXNlciI8L0Z1bGxOYW1lPg0KICAgICAgICAgICAgICAgIDxPcmdhbml6YXRpb24+PCFbQ0RBVEFbYm5nbGFiLnBzZWN1cmUubmV0XV0+PC9Pcmdhbml6YXRpb24+DQogICAgICAgICAgICA8L1VzZXJEYXRhPg0KICAgICAgICAgICAgPEltYWdlSW5zdGFsbD4NCiAgICAgICAgICAgICAgICA8T1NJbWFnZT4NCiAgICAgICAgICAgICAgICAgICAgPEluc3RhbGxUb0F2YWlsYWJsZVBhcnRpdGlvbj50cnVlPC9JbnN0YWxsVG9BdmFpbGFibGVQYXJ0aXRpb24+DQogICAgICAgICAgICAgICAgPC9PU0ltYWdlPg0KICAgICAgICAgICAgPC9JbWFnZUluc3RhbGw+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLUludGVybmF0aW9uYWwtQ29yZS1XaW5QRSIgcHJvY2Vzc29yQXJjaGl0ZWN0dXJlPSJ4ODYiIHB1YmxpY0tleVRva2VuPSIzMWJmMzg1NmFkMzY0ZTM1IiBsYW5ndWFnZT0ibmV1dHJhbCIgdmVyc2lvblNjb3BlPSJub25TeFMiIHhtbG5zOndjbT0iaHR0cDovL3NjaGVtYXMubWljcm9zb2Z0LmNvbS9XTUlDb25maWcvMjAwMi9TdGF0ZSIgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYS1pbnN0YW5jZSI+DQogICAgICAgICAgICA8U2V0dXBVSUxhbmd1YWdlPg0KICAgICAgICAgICAgICAgIDxVSUxhbmd1YWdlPjwhW0NEQVRBW2VuX1VTXV0+PC9VSUxhbmd1YWdlPg0KICAgICAgICAgICAgPC9TZXR1cFVJTGFuZ3VhZ2U+DQogICAgICAgICAgICA8SW5wdXRMb2NhbGU+PCFbQ0RBVEFbZW5fVVNdXT48L0lucHV0TG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgICAgICA8U3lzdGVtTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9TeXN0ZW1Mb2NhbGU+DQogICAgICAgICAgICA8VXNlckxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvVXNlckxvY2FsZT4NCiAgICAgICAgPC9jb21wb25lbnQ+DQogICAgPC9zZXR0aW5ncz4NCiAgICA8c2V0dGluZ3MgcGFzcz0ic3BlY2lhbGl6ZSI+DQogICAgICAgIDxjb21wb25lbnQgbmFtZT0iTWljcm9zb2Z0LVdpbmRvd3MtU2hlbGwtU2V0dXAiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPERpc3BsYXk+DQogICAgICAgICAgICAgICAgPENvbG9yRGVwdGg+MzI8L0NvbG9yRGVwdGg+DQogICAgICAgICAgICAgICAgPERQST45NjwvRFBJPg0KICAgICAgICAgICAgICAgIDxIb3Jpem9udGFsUmVzb2x1dGlvbj4xMDI0PC9Ib3Jpem9udGFsUmVzb2x1dGlvbj4NCiAgICAgICAgICAgICAgICA8UmVmcmVzaFJhdGU+NzU8L1JlZnJlc2hSYXRlPg0KICAgICAgICAgICAgICAgIDxWZXJ0aWNhbFJlc29sdXRpb24+NzY4PC9WZXJ0aWNhbFJlc29sdXRpb24+DQogICAgICAgICAgICA8L0Rpc3BsYXk+DQogICAgICAgICAgICA8Q29tcHV0ZXJOYW1lPjwhW0NEQVRBW1Rlc3Qtd2luOC0xXV0+PC9Db21wdXRlck5hbWU+DQogICAgICAgICAgICA8VGltZVpvbmU+PCFbQ0RBVEFbR01UIFN0YW5kYXJkIFRpbWVdXT48L1RpbWVab25lPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICAgICAgPGNvbXBvbmVudCBuYW1lPSJNaWNyb3NvZnQtV2luZG93cy1JbnRlcm5hdGlvbmFsLUNvcmUiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElucHV0TG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9JbnB1dExvY2FsZT4NCiAgICAgICAgICAgIDxVc2VyTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9Vc2VyTG9jYWxlPg0KICAgICAgICAgICAgPFN5c3RlbUxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvU3lzdGVtTG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLVVuYXR0ZW5kZWRKb2luIiBwcm9jZXNzb3JBcmNoaXRlY3R1cmU9ImFtZDY0IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElkZW50aWZpY2F0aW9uPg0KICAgICAgICAgICAgICAgIDxDcmVkZW50aWFscz4NCiAgICAgICAgICAgICAgICAgICAgPERvbWFpbj48IVtDREFUQVtdXT48L0RvbWFpbj4NCiAgICAgICAgICAgICAgICAgICAgPFBhc3N3b3JkPjwhW0NEQVRBW11dPjwvUGFzc3dvcmQ+DQogICAgICAgICAgICAgICAgICAgIDxVc2VybmFtZT48IVtDREFUQVtdXT48L1VzZXJuYW1lPg0KICAgICAgICAgICAgICAgIDwvQ3JlZGVudGlhbHM+DQogICAgICAgICAgICAgICAgPEpvaW5Eb21haW4+PCFbQ0RBVEFbXV0+PC9Kb2luRG9tYWluPg0KICAgICAgICAgICAgICAgIDxNYWNoaW5lT2JqZWN0T1U+PCFbQ0RBVEFbXV0+PC9NYWNoaW5lT2JqZWN0T1U+DQogICAgICAgICAgICA8L0lkZW50aWZpY2F0aW9uPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICA8L3NldHRpbmdzPg0KICAgIDxzZXR0aW5ncyBwYXNzPSJvb2JlU3lzdGVtIj4NCiAgICAgICAgPGNvbXBvbmVudCBuYW1lPSJNaWNyb3NvZnQtV2luZG93cy1JbnRlcm5hdGlvbmFsLUNvcmUiIHByb2Nlc3NvckFyY2hpdGVjdHVyZT0ieDg2IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPElucHV0TG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9JbnB1dExvY2FsZT4NCiAgICAgICAgICAgIDxVc2VyTG9jYWxlPjwhW0NEQVRBW2VuX1VTXV0+PC9Vc2VyTG9jYWxlPg0KICAgICAgICAgICAgPFN5c3RlbUxvY2FsZT48IVtDREFUQVtlbl9VU11dPjwvU3lzdGVtTG9jYWxlPg0KICAgICAgICAgICAgPFVJTGFuZ3VhZ2U+PCFbQ0RBVEFbZW5fVVNdXT48L1VJTGFuZ3VhZ2U+DQogICAgICAgIDwvY29tcG9uZW50Pg0KICAgICAgICA8Y29tcG9uZW50IG5hbWU9Ik1pY3Jvc29mdC1XaW5kb3dzLVNoZWxsLVNldHVwIiBwcm9jZXNzb3JBcmNoaXRlY3R1cmU9ImFtZDY0IiBwdWJsaWNLZXlUb2tlbj0iMzFiZjM4NTZhZDM2NGUzNSIgbGFuZ3VhZ2U9Im5ldXRyYWwiIHZlcnNpb25TY29wZT0ibm9uU3hTIiB4bWxuczp3Y209Imh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vV01JQ29uZmlnLzIwMDIvU3RhdGUiIHhtbG5zOnhzaT0iaHR0cDovL3d3dy53My5vcmcvMjAwMS9YTUxTY2hlbWEtaW5zdGFuY2UiPg0KICAgICAgICAgICAgPE9PQkU+DQogICAgICAgICAgICAgICAgPFByb3RlY3RZb3VyUEM+MjwvUHJvdGVjdFlvdXJQQz4NCiAgICAgICAgICAgICAgICA8TmV0d29ya0xvY2F0aW9uPldvcms8L05ldHdvcmtMb2NhdGlvbj4NCiAgICAgICAgICAgICAgICA8SGlkZUVVTEFQYWdlPnRydWU8L0hpZGVFVUxBUGFnZT4NCiAgICAgICAgICAgIDwvT09CRT4NCiAgICAgICAgICAgIDxVc2VyQWNjb3VudHM+DQogICAgICAgICAgICAgICAgPEFkbWluaXN0cmF0b3JQYXNzd29yZD4NCiAgICAgICAgICAgICAgICAgICAgPFZhbHVlPjwhW0NEQVRBW0VtYmUxbXBsc11dPjwvVmFsdWU+DQogICAgICAgICAgICAgICAgICAgIDxQbGFpblRleHQ+dHJ1ZTwvUGxhaW5UZXh0Pg0KICAgICAgICAgICAgICAgIDwvQWRtaW5pc3RyYXRvclBhc3N3b3JkPg0KICAgICAgICAgICAgICAgIDxMb2NhbEFjY291bnRzPg0KICAgICAgICAgICAgICAgICAgICA8TG9jYWxBY2NvdW50IHdjbTphY3Rpb249ImFkZCI+DQogICAgICAgICAgICAgICAgICAgICAgICA8UGFzc3dvcmQ+DQogICAgICAgICAgICAgICAgICAgICAgICAgICAgPFZhbHVlPjwhW0NEQVRBW0VtYmUxbXBsc11dPjwvVmFsdWU+DQogICAgICAgICAgICAgICAgICAgICAgICAgICAgPFBsYWluVGV4dD50cnVlPC9QbGFpblRleHQ+DQogICAgICAgICAgICAgICAgICAgICAgICA8L1Bhc3N3b3JkPg0KICAgICAgICAgICAgICAgICAgICAgICAgPEdyb3VwPmFkbWluaXN0cmF0b3JzPC9Hcm91cD4NCiAgICAgICAgICAgICAgICAgICAgICAgIDxOYW1lPnVzZXI8L05hbWU+DQogICAgICAgICAgICAgICAgICAgICAgICA8RGlzcGxheU5hbWU+dXNlcjwvRGlzcGxheU5hbWU+DQogICAgICAgICAgICAgICAgICAgIDwvTG9jYWxBY2NvdW50Pg0KICAgICAgICAgICAgICAgIDwvTG9jYWxBY2NvdW50cz4NCiAgICAgICAgICAgIDwvVXNlckFjY291bnRzPg0KICAgICAgICA8L2NvbXBvbmVudD4NCiAgICA8L3NldHRpbmdzPg0KICAgIDxjcGk6b2ZmbGluZUltYWdlIGNwaTpzb3VyY2U9IndpbTpkOi9zb3VyY2VzL2luc3RhbGwud2ltI1dpbmRvd3MgOCBFTlRFUlBSSVNFIiB4bWxuczpjcGk9InVybjpzY2hlbWFzLW1pY3Jvc29mdC1jb206Y3BpIi8+DQo8L3VuYXR0ZW5kPg0K'}}}, u'readonly': 'True', 'deviceType': u'disk', u'deviceId': u'c86868ec-4eae-4fb4-b395-165fd3d31ac2', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'floppy', u'shared': u'false', u'path':
u'/var/run/vdsm/payload/523a9aa2-f60c-4cd7-963a-da678e692218.3b185f2c896bd91b66d6a3959677f177.img', u'type': u'disk'}, {u'index': u'2', u'iface': u'ide', 'name': u'hdc', 'alias': u'ide0-1-0', u'specParams': {u'path': u''}, u'readonly': 'True', 'deviceType': u'disk', u'deviceId': u'fc33f0e3-3a7c-4dc2-a4c5-0d8134766c4d', 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111/ovirt-guest-tools-3.5_5.iso', u'type': u'disk'}, {u'poolID': u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', 'volumeInfo': {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224', 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a'}, u'index': 0, u'iface': u'ide', 'apparentsize': '197120', u'specParams': {}, u'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224', u'readonly': 'False', 'deviceType': u'disk', u'shared': u'false', 'truesize': '200704', u'type': u'disk', u'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'reqsize': '0', u'format': u'cow', u'deviceId': u'91dce925-129e-4de5-a5af-bbdbe9d80224', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'disk', 'path':
u'/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a', u'propagateErrors': u'off', u'optional': u'false', 'name': u'hda', u'bootOrder': u'1', u'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'alias': u'ide0-0-0', 'volumeChain': [{'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'volumeID': u'27589b5c-0c6f-4551-8199-e80c870c9d2a', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224', 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/27589b5c-0c6f-4551-8199-e80c870c9d2a'}, {'domainID': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'volType': 'path', 'leaseOffset': 0, 'volumeID': u'60d7aa2a-9850-43f2-a523-64c9dda8e403', 'leasePath':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403.lease', 'imageID': u'91dce925-129e-4de5-a5af-bbdbe9d80224', 'path':
u'/rhev/data-center/mnt/10.204.206.10:_ovirt/49d4a9cd-946d-41e0-a7ae-f2620f010302/images/91dce925-129e-4de5-a5af-bbdbe9d80224/60d7aa2a-9850-43f2-a523-64c9dda8e403'}]}, {'device': u'usb', 'alias': u'usb0', 'deviceType': 'controller', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': u'ide', 'alias': u'ide0', 'deviceType': 'controller', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {'device': u'unix', 'alias': u'channel0', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {'device': u'unix', 'alias': u'channel1', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {'device': u'spicevmc', 'alias': u'channel2', 'deviceType': u'channel', 'type': u'channel', 'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'3'}}], u'timeOffset': u'19800', u'maxVCpus': u'16', u'spiceSecureChannels':
u'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', u'display': u'qxl'}] Thread-493090::DEBUG::2015-10-19 07:24:26,128::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-493091::DEBUG::2015-10-19 07:24:26,239::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getSpmStatus' in bridge with {u'storagepoolID': u'a24369bc-3e57-451b-a21c-422c5aa7b1e5'} Thread-493091::DEBUG::2015-10-19 07:24:26,240::task::595::Storage.TaskManager.Task::(_updateState) Task=`013a1544-a6f2-4d68-aee8-1461690a64cd`::moving from state init -> state preparing Thread-493091::INFO::2015-10-19 07:24:26,240::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', options=None) Thread-493091::INFO::2015-10-19 07:24:26,256::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 13L}} Thread-493091::DEBUG::2015-10-19 07:24:26,256::task::1191::Storage.TaskManager.Task::(prepare) Task=`013a1544-a6f2-4d68-aee8-1461690a64cd`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 13L}} Thread-493091::DEBUG::2015-10-19 07:24:26,256::task::595::Storage.TaskManager.Task::(_updateState) Task=`013a1544-a6f2-4d68-aee8-1461690a64cd`::moving from state preparing -> state finished Thread-493091::DEBUG::2015-10-19
07:24:26,256::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-493091::DEBUG::2015-10-19
07:24:26,257::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493091::DEBUG::2015-10-19 07:24:26,257::task::993::Storage.TaskManager.Task::(_decref) Task=`013a1544-a6f2-4d68-aee8-1461690a64cd`::ref 0 aborting False Thread-493091::DEBUG::2015-10-19 07:24:26,257::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getSpmStatus' in bridge with {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 13L} Thread-493091::DEBUG::2015-10-19 07:24:26,257::stompReactor::162::yajsonrpc.StompServer::(send) Sending response Thread-493092::DEBUG::2015-10-19 07:24:26,264::__init__::481::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'StoragePool.getInfo' in bridge with {u'storagepoolID': u'a24369bc-3e57-451b-a21c-422c5aa7b1e5'} Thread-493092::DEBUG::2015-10-19 07:24:26,264::task::595::Storage.TaskManager.Task::(_updateState) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::moving from state init -> state preparing Thread-493092::INFO::2015-10-19 07:24:26,265::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=u'a24369bc-3e57-451b-a21c-422c5aa7b1e5', options=None) Thread-493092::DEBUG::2015-10-19
07:24:26,265::resourceManager::198::Storage.ResourceManager.Request::(__init__)
ResName=`Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5`ReqID=`6efea4e0-11ed-45d4-ba50-b382dc2aebc6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2632' at 'getStoragePoolInfo' Thread-493092::DEBUG::2015-10-19
07:24:26,265::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5' for lock type 'shared' Thread-493092::DEBUG::2015-10-19
07:24:26,266::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5' is free. Now locking as 'shared' (1 active user) Thread-493092::DEBUG::2015-10-19
07:24:26,266::resourceManager::238::Storage.ResourceManager.Request::(grant)
ResName=`Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5`ReqID=`6efea4e0-11ed-45d4-ba50-b382dc2aebc6`::Granted request Thread-493092::DEBUG::2015-10-19 07:24:26,266::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::_resourcesAcquired: Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5 (shared) Thread-493092::DEBUG::2015-10-19 07:24:26,266::task::993::Storage.TaskManager.Task::(_decref) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::ref 1 aborting False Dummy-330620::DEBUG::2015-10-19
07:24:26,269::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) dd
if=/rhev/data-center/a24369bc-3e57-451b-a21c-422c5aa7b1e5/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) Dummy-330620::DEBUG::2015-10-19
07:24:26,303::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0202981 s, 50.4 MB/s\n'; <rc> = 0 Thread-493092::INFO::2015-10-19 07:24:26,331::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'No Description', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 13L, 'domains':
u'342d943d-bccb-49eb-abf5-be9f5a2afbb5:Active,1484ea07-4269-44c4-a503-fa6bf43d8bd9:Active,49d4a9cd-946d-41e0-a7ae-f2620f010302:Active', 'master_uuid': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 5}, 'dominfo': {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'status': u'Active', 'diskfree': '24726470656', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '52710866944', 'version': 0}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'status': u'Active', 'diskfree': '70269272064', 'isoprefix': '', 'alerts': [], 'disktotal': '96726941696', 'version': 0}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'status': u'Active', 'diskfree': '2067892011008', 'isoprefix': '', 'alerts': [], 'disktotal': '2291345653760', 'version': 3}}} Thread-493092::DEBUG::2015-10-19 07:24:26,331::task::1191::Storage.TaskManager.Task::(prepare) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::finished: {'info': {'name': 'No Description', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 13L, 'domains':
u'342d943d-bccb-49eb-abf5-be9f5a2afbb5:Active,1484ea07-4269-44c4-a503-fa6bf43d8bd9:Active,49d4a9cd-946d-41e0-a7ae-f2620f010302:Active', 'master_uuid': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 5}, 'dominfo': {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'status': u'Active', 'diskfree': '24726470656', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '52710866944', 'version': 0}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'status': u'Active', 'diskfree': '70269272064', 'isoprefix': '', 'alerts': [], 'disktotal': '96726941696', 'version': 0}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'status': u'Active', 'diskfree': '2067892011008', 'isoprefix': '', 'alerts': [], 'disktotal': '2291345653760', 'version': 3}}} Thread-493092::DEBUG::2015-10-19 07:24:26,331::task::595::Storage.TaskManager.Task::(_updateState) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::moving from state preparing -> state finished Thread-493092::DEBUG::2015-10-19
07:24:26,331::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {u'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5': < ResourceRef 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5', isValid: 'True' obj: 'None'>} Thread-493092::DEBUG::2015-10-19
07:24:26,332::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-493092::DEBUG::2015-10-19
07:24:26,332::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5' Thread-493092::DEBUG::2015-10-19
07:24:26,332::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5' (0 active users) Thread-493092::DEBUG::2015-10-19
07:24:26,332::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5' is free, finding out if anyone is waiting for it. Thread-493092::DEBUG::2015-10-19
07:24:26,333::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a24369bc-3e57-451b-a21c-422c5aa7b1e5', Clearing records. Thread-493092::DEBUG::2015-10-19 07:24:26,333::task::993::Storage.TaskManager.Task::(_decref) Task=`48cbcbae-9b02-48a0-80da-ff7fde9c43b0`::ref 0 aborting False Thread-493092::DEBUG::2015-10-19 07:24:26,333::__init__::514::jsonrpc.JsonRpcServer::(_serveRequest) Return 'StoragePool.getInfo' in bridge with {'info': {'name': 'No Description', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'pool_status': 'connected', 'lver': 13L, 'domains':
u'342d943d-bccb-49eb-abf5-be9f5a2afbb5:Active,1484ea07-4269-44c4-a503-fa6bf43d8bd9:Active,49d4a9cd-946d-41e0-a7ae-f2620f010302:Active', 'master_uuid': u'49d4a9cd-946d-41e0-a7ae-f2620f010302', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 5}, 'dominfo': {u'342d943d-bccb-49eb-abf5-be9f5a2afbb5': {'status': u'Active', 'diskfree': '24726470656', 'isoprefix':
u'/rhev/data-center/mnt/10.204.207.171:_var_lib_exports_iso/342d943d-bccb-49eb-abf5-be9f5a2afbb5/images/11111111-1111-1111-1111-111111111111', 'alerts': [], 'disktotal': '52710866944', 'version': 0}, u'1484ea07-4269-44c4-a503-fa6bf43d8bd9': {'status': u'Active', 'diskfree': '70269272064', 'isoprefix': '', 'alerts': [], 'disktotal': '96726941696', 'version': 0}, u'49d4a9cd-946d-41e0-a7ae-f2620f010302': {'status': u'Active', 'diskfree': '2067892011008', 'isoprefix': '', 'alerts': [], 'disktotal': '2291345653760', 'version': 3}}} Thread-493092::DEBUG::2015-10-19 07:24:26,334::stompReactor::162::yajsonrpc.StompServer::(send) Sending response ^C[root@pbuovirt2 ~]# [root@infraesx2 ~]# [root@infraesx2 ~]# [root@infraesx2 ~]# [root@infraesx2 ~]# [root@infraesx2 ~]# tail -f /var/log/vdsm/ backup/ connectivity.log mom.log register.log supervdsm.log upgrade.log vdsm.log [root@infraesx2 ~]# tail -f /var/log/vdsm/vdsm.log BindingXMLRPC::INFO::2015-10-26 07:57:03,378::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43211 Thread-816::INFO::2015-10-26 07:57:03,379::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43211 started Thread-816::INFO::2015-10-26 07:57:03,381::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43211 stopped Reactor thread::INFO::2015-10-26
07:57:18,397::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:43212 Reactor thread::DEBUG::2015-10-26
07:57:18,406::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2015-10-26
07:57:18,406::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:43212 Reactor thread::DEBUG::2015-10-26 07:57:18,406::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 43212) BindingXMLRPC::INFO::2015-10-26 07:57:18,407::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43212 Thread-817::INFO::2015-10-26 07:57:18,408::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43212 started Thread-817::INFO::2015-10-26 07:57:18,410::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43212 stopped Thread-818::DEBUG::2015-10-26 07:57:32,985::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getCapabilities' in bridge with {} Thread-818::DEBUG::2015-10-26 07:57:33,005::utils::661::root::(execCmd) /usr/sbin/tc qdisc show (cwd None) Thread-818::DEBUG::2015-10-26 07:57:33,015::utils::679::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0 Thread-818::DEBUG::2015-10-26 07:57:33,026::__init__::534::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getCapabilities' in bridge with {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:fbb518530'}], 'FC': []}, 'packages2': {'kernel': {'release': '229.11.1.el7.x86_64', 'buildtime': 1438823178.0, 'version': '3.10.0'}, 'spice-server': {'release': '9.el7', 'buildtime': 1426031557L, 'version': '0.12.4'}, 'librbd1': {'release': '2.el7', 'buildtime': 1425594433L, 'version': '0.80.7'}, 'vdsm': {'release': '4.git6d8c446.el7', 'buildtime': 1441206355L, 'version': '4.17.4'}, 'qemu-kvm': {'release': '23.el7_1.6.1', 'buildtime': 1438078890L, 'version': '2.1.2'}, 'libvirt': {'release': '16.el7_1.3', 'buildtime': 1431461920L, 'version': '1.2.8'}, 'qemu-img': {'release': '23.el7_1.6.1', 'buildtime': 1438078890L, 'version': '2.1.2'}, 'mom': {'release': '1.el7', 'buildtime': 1436818826L, 'version': '0.5.0'}, 'glusterfs-cli': {'release': '0.820.git092cc95.el7.centos', 'buildtime': 1441215385L, 'version': '3.8dev'}}, 'numaNodeDistance': {'1': [20, 10], '0': [10, 20]}, 'cpuModel': 'Intel(R) Xeon(R) CPU E5520 @ 2.27GHz', 'liveMerge': 'true', 'hooks': {'before_vm_start': {'50_hostedengine': {'md5': '2a6d96c26a3599812be6cf1a13d9f485'}}, 'after_network_setup': {'30_ethtool_options': {'md5': '9cdcf29a16651eb3abfda900312e8b31'}}}, 'vmTypes': ['kvm'], 'selinux': {'mode': '1'}, 'liveSnapshot': 'true', 'kdumpStatus': 0, 'networks': {}, 'bridges': {}, 'uuid': '33343934-3932-4753-4839-333858425450', 'onlineCpus': '0,2,4,6,8,10,12,14,1,3,5,7,9,11,13,15', 'nics': {'enp3s0f1': {'addr': '', 'ipv6gateway': '::', 'ipv6addrs': [], 'mtu': '1500', 'dhcpv4': False, 'netmask': '', 'dhcpv6': False, 'ipv4addrs': [], 'cfg': {'BOOTPROTO': 'none'}, 'hwaddr': '00:26:55:4c:42:d2', 'speed': 0, 'gateway': ''}, 'enp3s0f0': {'addr': '', 'ipv6gateway': '::', 'ipv6addrs': [], 'mtu': '1500', 'dhcpv4': False, 'netmask': '', 'dhcpv6': False, 'ipv4addrs': [], 'cfg': {'BOOTPROTO': 'none'}, 'hwaddr': '00:26:55:4c:42:d0', 'speed': 0, 'gateway': ''}, 'enp2s0f0': {'addr': '10.206.68.97', 'ipv6gateway': '::', 'ipv6addrs': ['fe80::226:55ff:fe4c:42cc/64'], 'mtu': '1500', 'dhcpv4': False, 'netmask': '255.255.254.0', 'dhcpv6': False, 'ipv4addrs': ['10.206.68.97/23'], 'cfg': {'IPV6INIT': 'no', 'NM_CONTROLLED': 'no', 'IPADDR': '10.206.68.97', 'PEERDNS': 'no', 'ONBOOT': 'yes', 'IPV6_AUTOCONF': 'no', 'HWADDR': '00:26:55:4c:42:cc', 'NETMASK': '255.255.254.0', 'BOOTPROTO': 'none', 'DEVICE': 'enp2s0f0', 'PEERNTP': 'yes', 'GATEWAY': '10.206.69.254'}, 'hwaddr': '00:26:55:4c:42:cc', 'speed': 1000, 'gateway': '10.206.69.254'}, 'enp2s0f1': {'addr': '', 'ipv6gateway': '::', 'ipv6addrs': [], 'mtu': '1500', 'dhcpv4': False, 'netmask': '', 'dhcpv6': False, 'ipv4addrs': [], 'cfg': {'BOOTPROTO': 'none'}, 'hwaddr': '00:26:55:4c:42:ce', 'speed': 0, 'gateway': ''}}, 'software_revision': '4', 'hostdevPassthrough': 'false', 'clusterLevels': ['3.4', '3.5', '3.6'], 'cpuFlags':
'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:fbb518530', 'netConfigDirty': 'True', 'supportedENGINEs': ['3.4', '3.5', '3.6'], 'autoNumaBalancing': 1, 'additionalFeatures': [], 'reservedMem': '321', 'bondings': {}, 'software_version': '4.17', 'memSize': '23843', 'cpuSpeed': '2266.000', 'numaNodes': {'1': {'totalMemory': '12287', 'cpus': [1, 3, 5, 7, 9, 11, 13, 15]}, '0': {'totalMemory': '12277', 'cpus': [0, 2, 4, 6, 8, 10, 12, 14]}}, 'cpuSockets': '2', 'vlans': {}, 'lastClientIface': 'enp2s0f0', 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'version_name': 'Snow Man', 'cpuThreads': '16', 'emulatedMachines': ['pc-i440fx-rhel7.1.0', 'rhel6.3.0', 'pc-q35-rhel7.0.0', 'rhel6.1.0', 'rhel6.6.0', 'rhel6.2.0', 'pc', 'pc-q35-rhel7.1.0', 'q35', 'rhel6.4.0', 'rhel6.0.0', 'rhel6.5.0', 'pc-i440fx-rhel7.0.0'], 'rngSources': ['random'], 'operatingSystem': {'release': '0.999.201509030901.el7.centos', 'version': '3.6', 'name': 'oVirt Node'}} Thread-818::DEBUG::2015-10-26 07:57:33,027::stompreactor::304::yajsonrpc.StompServer::(send) Sending response Thread-819::DEBUG::2015-10-26 07:57:33,034::__init__::503::jsonrpc.JsonRpcServer::(_serveRequest) Calling 'Host.getHardwareInfo' in bridge with {} Thread-819::DEBUG::2015-10-26 07:57:33,037::__init__::534::jsonrpc.JsonRpcServer::(_serveRequest) Return 'Host.getHardwareInfo' in bridge with {'systemProductName': 'ProLiant DL380 G6', 'systemUUID': '33343934-3932-4753-4839-333858425450', 'systemSerialNumber': 'SGH938XBTP', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'} Thread-819::DEBUG::2015-10-26 07:57:33,038::stompreactor::304::yajsonrpc.StompServer::(send) Sending response Reactor thread::INFO::2015-10-26
07:57:33,426::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:43213 Reactor thread::DEBUG::2015-10-26
07:57:33,434::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2015-10-26
07:57:33,435::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:43213 Reactor thread::DEBUG::2015-10-26 07:57:33,435::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 43213) BindingXMLRPC::INFO::2015-10-26 07:57:33,435::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43213 Thread-820::INFO::2015-10-26 07:57:33,436::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43213 started Thread-820::INFO::2015-10-26 07:57:33,438::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43213 stopped Thread-821::DEBUG::2015-10-26 07:57:35,579::stompreactor::304::yajsonrpc.StompServer::(send) Sending response Reactor thread::INFO::2015-10-26
07:57:48,453::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:43214 Reactor thread::DEBUG::2015-10-26
07:57:48,461::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2015-10-26
07:57:48,462::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:43214 Reactor thread::DEBUG::2015-10-26 07:57:48,462::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 43214) BindingXMLRPC::INFO::2015-10-26 07:57:48,462::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43214 Thread-822::INFO::2015-10-26 07:57:48,463::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43214 started Thread-822::INFO::2015-10-26 07:57:48,465::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43214 stopped Reactor thread::INFO::2015-10-26
07:58:03,480::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:43215 Reactor thread::DEBUG::2015-10-26
07:58:03,488::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2015-10-26
07:58:03,489::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:43215 Reactor thread::DEBUG::2015-10-26 07:58:03,489::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 43215) BindingXMLRPC::INFO::2015-10-26 07:58:03,489::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43215 Thread-823::INFO::2015-10-26 07:58:03,490::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43215 started Thread-823::INFO::2015-10-26 07:58:03,492::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43215 stopped Reactor thread::INFO::2015-10-26
07:58:18,507::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:43216 Reactor thread::DEBUG::2015-10-26
07:58:18,515::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11 Reactor thread::INFO::2015-10-26
07:58:18,516::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:43216 Reactor thread::DEBUG::2015-10-26 07:58:18,516::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 43216) BindingXMLRPC::INFO::2015-10-26 07:58:18,516::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:43216 Thread-824::INFO::2015-10-26 07:58:18,517::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43216 started Thread-824::INFO::2015-10-26 07:58:18,519::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:43216 stopped ^C [root@infraesx2 ~]#
On Mon, Oct 26, 2015 at 1:20 PM, Piotr Kliczewski <piotr.kliczewski@gmail.com> wrote:
Based on provided snippet of a log the engine is not able to connect to your vdsm due to timeout (by default 2 seconds). Please provide vdsm log so we can see why it failed.
On Mon, Oct 26, 2015 at 7:14 AM, Budur Nagaraju <nbudoor@gmail.com> wrote: > HI > > After installing ovirt 3.6,unable to add ovirt node to the ovirt > application > ,below are the logs. > The moment I add to ovirt application network is getting > disconnected > prior > to that ovirt node was able to reach the gateway without any > issues. > > > any solution that wold resolve my issues ? > > > > 2015-10-21 17:44:44,179 INFO > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp > Reactor) > [] Connecting to infraesx2.bnglab.psecure.net/10.206.68.97 > 2015-10-21 17:44:46,179 WARN > [org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable] (SSL Stomp > Reactor) [] > Retry failed > 2015-10-21 17:44:46,179 ERROR > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] > (DefaultQuartzScheduler_Worker-40) [] Exception during connection > 2015-10-21 17:44:46,179 ERROR > > [org.ovirt.engine.core.vdsbroker.vdsbroker.GetAllVmStatsVDSCommand] > (DefaultQuartzScheduler_Worker-40) [] Command > 'GetAllVmStatsVDSCommand(HostName = infraesx2, > VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', > hostId='2d74bd31-6894-4c9c-8260-97c305a6998c', > vds='Host[infraesx2,2d74bd31-6894-4c9c-8260-97c305a6998c]'})' > execution > failed: java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:46,179 INFO > [org.ovirt.engine.core.vdsbroker.PollVmStatsRefresher] > (DefaultQuartzScheduler_Worker-40) [] Failed to fetch vms info for > host > 'infraesx2' - skipping VMs monitoring. > 2015-10-21 17:44:46,179 INFO > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp > Reactor) > [] Connecting to infraesx2.bnglab.psecure.net/10.206.68.97 > 2015-10-21 17:44:48,179 WARN > [org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable] (SSL Stomp > Reactor) [] > Retry failed > 2015-10-21 17:44:48,179 ERROR > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] > (DefaultQuartzScheduler_Worker-41) [] Exception during connection > 2015-10-21 17:44:48,179 ERROR > > [org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand] > (DefaultQuartzScheduler_Worker-41) [] Command > 'GetCapabilitiesVDSCommand(HostName = infraesx2, > VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', > hostId='2d74bd31-6894-4c9c-8260-97c305a6998c', > vds='Host[infraesx2,2d74bd31-6894-4c9c-8260-97c305a6998c]'})' > execution > failed: java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:48,179 ERROR > [org.ovirt.engine.core.vdsbroker.HostMonitoring] > (DefaultQuartzScheduler_Worker-41) [] Failure to refresh Vds > runtime > info: > java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:48,179 ERROR > [org.ovirt.engine.core.vdsbroker.HostMonitoring] > (DefaultQuartzScheduler_Worker-41) [] Exception: > org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: > java.rmi.ConnectException: Connection timeout > at > > > > org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:157) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:120) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:65) > [vdsbroker.jar:] > at > > > org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) > [dal.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:467) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:634) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.HostMonitoring.refreshVdsRunTimeInfo(HostMonitoring.java:119) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.HostMonitoring.refresh(HostMonitoring.java:84) > [vdsbroker.jar:] > at > > > org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:226) > [vdsbroker.jar:] > at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown > Source) > [:1.7.0_85] > at > > > > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [rt.jar:1.7.0_85] > at java.lang.reflect.Method.invoke(Method.java:606) > [rt.jar:1.7.0_85] > at > > > > org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:81) > [scheduler.jar:] > at > > > org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:52) > [scheduler.jar:] > at org.quartz.core.JobRunShell.run(JobRunShell.java:213) > [quartz.jar:] > at > > > > org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) > [quartz.jar:] > Caused by: java.rmi.ConnectException: Connection timeout > at > > > > org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient$1.call(ReactorClient.java:116) > [vdsm-jsonrpc-java-client.jar:] > at > > > > org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient$1.call(ReactorClient.java:100) > [vdsm-jsonrpc-java-client.jar:] > at > > > > org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable.call(Retryable.java:27) > [vdsm-jsonrpc-java-client.jar:] > at > java.util.concurrent.FutureTask.run(FutureTask.java:262) > [rt.jar:1.7.0_85] > at > > > > org.ovirt.vdsm.jsonrpc.client.utils.ReactorScheduler.performPendingOperations(ReactorScheduler.java:28) > [vdsm-jsonrpc-java-client.jar:] > at > > org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.run(Reactor.java:61) > [vdsm-jsonrpc-java-client.jar:] > > 2015-10-21 17:44:51,182 INFO > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp > Reactor) > [] Connecting to infraesx2.bnglab.psecure.net/10.206.68.97 > 2015-10-21 17:44:53,183 WARN > [org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable] (SSL Stomp > Reactor) [] > Retry failed > 2015-10-21 17:44:53,183 ERROR > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] > (DefaultQuartzScheduler_Worker-14) [22712a82] Exception during > connection > 2015-10-21 17:44:53,183 ERROR > > [org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand] > (DefaultQuartzScheduler_Worker-14) [22712a82] Command > 'GetCapabilitiesVDSCommand(HostName = infraesx2, > VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', > hostId='2d74bd31-6894-4c9c-8260-97c305a6998c', > vds='Host[infraesx2,2d74bd31-6894-4c9c-8260-97c305a6998c]'})' > execution > failed: java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:53,183 ERROR > [org.ovirt.engine.core.vdsbroker.HostMonitoring] > (DefaultQuartzScheduler_Worker-14) [22712a82] Failure to refresh > Vds > runtime > info: java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:53,183 ERROR > [org.ovirt.engine.core.vdsbroker.HostMonitoring] > (DefaultQuartzScheduler_Worker-14) [22712a82] Exception: > org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: > java.rmi.ConnectException: Connection timeout > at > > > > org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:157) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:120) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:65) > [vdsbroker.jar:] > at > > > org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) > [dal.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:467) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:634) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.HostMonitoring.refreshVdsRunTimeInfo(HostMonitoring.java:119) > [vdsbroker.jar:] > at > > > > org.ovirt.engine.core.vdsbroker.HostMonitoring.refresh(HostMonitoring.java:84) > [vdsbroker.jar:] > at > > > org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:226) > [vdsbroker.jar:] > at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown > Source) > [:1.7.0_85] > at > > > > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [rt.jar:1.7.0_85] > at java.lang.reflect.Method.invoke(Method.java:606) > [rt.jar:1.7.0_85] > at > > > > org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:81) > [scheduler.jar:] > at > > > org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:52) > [scheduler.jar:] > at org.quartz.core.JobRunShell.run(JobRunShell.java:213) > [quartz.jar:] > at > > > > org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) > [quartz.jar:] > Caused by: java.rmi.ConnectException: Connection timeout > at > > > > org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient$1.call(ReactorClient.java:116) > [vdsm-jsonrpc-java-client.jar:] > at > > > > org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient$1.call(ReactorClient.java:100) > [vdsm-jsonrpc-java-client.jar:] > at > > > > org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable.call(Retryable.java:27) > [vdsm-jsonrpc-java-client.jar:] > at > java.util.concurrent.FutureTask.run(FutureTask.java:262) > [rt.jar:1.7.0_85] > at > > > > org.ovirt.vdsm.jsonrpc.client.utils.ReactorScheduler.performPendingOperations(ReactorScheduler.java:28) > [vdsm-jsonrpc-java-client.jar:] > at > > org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.run(Reactor.java:61) > [vdsm-jsonrpc-java-client.jar:] > > 2015-10-21 17:44:56,187 INFO > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp > Reactor) > [] Connecting to infraesx2.bnglab.psecure.net/10.206.68.97 > 2015-10-21 17:44:58,187 WARN > [org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable] (SSL Stomp > Reactor) [] > Retry failed > 2015-10-21 17:44:58,187 ERROR > [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] > (DefaultQuartzScheduler_Worker-11) [] Exception during connection > 2015-10-21 17:44:58,187 ERROR > > [org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand] > (DefaultQuartzScheduler_Worker-11) [] Command > 'GetCapabilitiesVDSCommand(HostName = infraesx2, > VdsIdAndVdsVDSCommandParametersBase:{runAsync='true', > hostId='2d74bd31-6894-4c9c-8260-97c305a6998c', > vds='Host[infraesx2,2d74bd31-6894-4c9c-8260-97c305a6998c]'})' > execution > failed: java.rmi.ConnectException: Connection timeout > 2015-10-21 17:44:5
...
[Message clipped]